PR#296: Add time_started to mark transition from waiting to generating - odcs

odcs

#296 Add time_started to mark transition from waiting to generating

Merged 4 years ago by jkaluza. Opened 4 years ago by lsedlar.

lsedlar/odcs time_started into master

Fail generating composes based on time started

Lubomír Sedlář • 4 years ago

a9bf78a

Add time_started filed to composes

Lubomír Sedlář • 4 years ago

29dcf86

server/odcs/server/backend.py

file modified

+1 -1

		`@@ -924,7 +924,7 @@`
		`# Get composes which are in 'generating' state for too long.`
		`composes = Compose.query.filter(`
		`Compose.state == COMPOSE_STATES["generating"],`
		`- Compose.time_submitted < too_old_datetime).order_by(`
		`+ Compose.time_started < too_old_datetime).order_by(`
		`Compose.id).all()`

		`for compose in composes:`

server/odcs/server/migrations/versions/de0a86d7de49_.py

file added

+28

		`@@ -0,0 +1,28 @@`
		`+ """empty message`
		`+`
		`+ Revision ID: de0a86d7de49`
		`+ Revises: e186faabdafe`
		`+ Create Date: 2019-09-24 12:31:18.648835`
		`+`
		`+ """`
		`+`
		`+ # revision identifiers, used by Alembic.`
		`+ revision = 'de0a86d7de49'`
		`+ down_revision = 'e186faabdafe'`
		`+`
		`+ from alembic import op`
		`+ import sqlalchemy as sa`
		`+`
		`+`
		`+ def upgrade():`
		`+ # ### commands auto generated by Alembic - please adjust! ###`
		`+ op.add_column('composes', sa.Column('time_started', sa.DateTime(), nullable=True))`
		`+ # ### end Alembic commands ###`
		`+ # Set the start time for all composes that are not waiting.`
		`+ op.execute("UPDATE composes SET time_started = time_submitted WHERE time_started IS NULL AND state != 0")`
		`+`
		`+`
		`+ def downgrade():`
		`+ # ### commands auto generated by Alembic - please adjust! ###`
		`+ op.drop_column('composes', 'time_started')`
		`+ # ### end Alembic commands ###`

server/odcs/server/models.py

file modified

+10

		`@@ -124,9 +124,16 @@`
		`builds = db.Column(db.String)`
		`# COMPOSE_FLAGS`
		`flags = db.Column(db.Integer)`
		`+ # Time when the compose should be deleted`
		`time_to_expire = db.Column(db.DateTime, nullable=False, index=True)`
		`+ # Time when the request for compose was submitted to ODCS`
		`time_submitted = db.Column(db.DateTime, nullable=False)`
		`+ # Time when compose transitioned from WAITING to GENERATING`
		`+ time_started = db.Column(db.DateTime)`
		`+ # Time when compose was successfully finished. Failed composes do not have`
		`+ # this time.`
		`time_done = db.Column(db.DateTime)`
		`+ # Time when compose was deleted`
		`time_removed = db.Column(db.DateTime)`
		`# removed_by is set when compose is deleted rather than expired normally`
		`removed_by = db.Column(db.String, nullable=True)`
		`@@ -315,6 +322,7 @@`
		`'state_reason': self.state_reason,`
		`'time_to_expire': self._utc_datetime_to_iso(self.time_to_expire),`
		`'time_submitted': self._utc_datetime_to_iso(self.time_submitted),`
		`+ 'time_started': self._utc_datetime_to_iso(self.time_started),`
		`'time_done': self._utc_datetime_to_iso(self.time_done),`
		`'time_removed': self._utc_datetime_to_iso(self.time_removed),`
		`'removed_by': self.removed_by,`
		`@@ -392,6 +400,8 @@`
		`self.time_removed = happen_on or datetime.utcnow()`
		`elif to_state == COMPOSE_STATES['done']:`
		`self.time_done = happen_on or datetime.utcnow()`
		`+ elif to_state == COMPOSE_STATES['generating']:`
		`+ self.time_started = happen_on or datetime.utcnow()`
		`if to_state in (COMPOSE_STATES["done"], COMPOSE_STATES["failed"]):`
		`ttl = self.time_to_expire - self.time_submitted`
		`self.time_to_expire = (happen_on or datetime.utcnow()) + ttl`

server/tests/test_composerthread.py

file modified

+15 -4

		`@@ -374,6 +374,7 @@`
		`self.patch_generate_new_compose.stop()`

		`def _add_test_compose(self, state, time_submitted=None,`
		`+ time_started=None,`
		`source_type=PungiSourceType.KOJI_TAG):`
		`compose = Compose.create(`
		`db.session, "unknown", source_type, "f26",`
		`@@ -381,6 +382,8 @@`
		`compose.state = state`
		`if time_submitted:`
		`compose.time_submitted = time_submitted`
		`+ if time_started:`
		`+ compose.time_started = time_started`
		`db.session.add(compose)`
		`db.session.commit()`
		`return compose`
		`@@ -446,13 +449,21 @@`
		`def test_fail_lost_generating_composes(self):`
		`t = datetime.utcnow() - timedelta(seconds=2 * conf.pungi_timeout)`

		`- time_submitted = t - timedelta(minutes=5)`
		`+ time_submitted = t - timedelta(minutes=6)`
		`+ time_started = t - timedelta(minutes=5)`
		`compose_to_fail = self._add_test_compose(`
		`- COMPOSE_STATES["generating"], time_submitted=time_submitted)`
		`+ COMPOSE_STATES["generating"],`
		`+ time_submitted=time_submitted,`
		`+ time_started=time_started,`
		`+ )`

		`- time_submitted = t + timedelta(minutes=5)`
		`+ time_submitted = t + timedelta(minutes=4)`
		`+ time_started = t + timedelta(minutes=5)`
		`compose_to_keep = self._add_test_compose(`
		`- COMPOSE_STATES["generating"], time_submitted=time_submitted)`
		`+ COMPOSE_STATES["generating"],`
		`+ time_submitted=time_submitted,`
		`+ time_started=time_started,`
		`+ )`

		`self.composer.fail_lost_generating_composes()`
		`db.session.commit()`

server/tests/test_models.py

file modified

+9 -1

		`@@ -58,6 +58,7 @@`
		`'result_repo': 'http://localhost/odcs/latest-odcs-1-1/compose/Temporary',`
		`'result_repofile': 'http://localhost/odcs/latest-odcs-1-1/compose/Temporary/odcs-1.repo',`
		`'time_submitted': c.json()["time_submitted"], 'id': 1,`
		`+ 'time_started': None,`
		`'time_removed': None,`
		`'removed_by': None,`
		`'time_to_expire': c.json()["time_to_expire"],`
		`@@ -110,7 +111,8 @@`
		`# in create_copy() method.`
		`if c.name in ["id", "state", "state_reason", "time_to_expire",`
		`"time_done", "time_submitted", "time_removed",`
		`- "removed_by", "reused_id", "koji_task_id"]:`
		`+ "removed_by", "reused_id", "koji_task_id",`
		`+ "time_started"]:`
		`assertMethod = self.assertNotEqual`
		`else:`
		`assertMethod = self.assertEqual`
		`@@ -231,3 +233,9 @@`
		`# so that it expires in about 6 minutes`
		`expires_in = self.c1.time_to_expire - now`
		`assert expires_in.total_seconds() == pytest.approx(360, abs=0.1)`
		`+`
		`+ def test_transition_to_generating_updates_time_started(self):`
		`+ now = datetime.utcnow()`
		`+ in_five_minutes = now + timedelta(seconds=300)`
		`+ self.c1.transition(COMPOSE_STATES["generating"], "it started", in_five_minutes)`
		`+ assert self.c1.time_started == in_five_minutes`

server/tests/test_views.py

file modified

		`@@ -292,6 +292,7 @@`
		`'result_repo': 'http://localhost/odcs/latest-odcs-%d-1/compose/Temporary' % data['id'],`
		`'result_repofile': 'http://localhost/odcs/latest-odcs-%d-1/compose/Temporary/odcs-%d.repo' % (data['id'], data['id']),`
		`'time_submitted': data["time_submitted"], 'id': data['id'],`
		`+ 'time_started': None,`
		`'time_removed': None,`
		`'removed_by': None,`
		`'time_to_expire': data["time_to_expire"],`
		`@@ -1068,6 +1069,7 @@`
		`'result_repo': 'http://localhost/odcs/latest-odcs-%d-1/compose/Temporary' % data['id'],`
		`'result_repofile': 'http://localhost/odcs/latest-odcs-%d-1/compose/Temporary/odcs-%d.repo' % (data['id'], data['id']),`
		`'time_submitted': data["time_submitted"], 'id': data['id'],`
		`+ 'time_started': None,`
		`'time_removed': None,`
		`'removed_by': None,`
		`'time_to_expire': data["time_to_expire"],`

lsedlar commented 4 years ago

The field can be empty, but all existing composes not in wait state will be initialized with the start time set to time_submitted by the migration. This should avoid the situation during update that some composes will be already generating and not have the time.

The function to fail stuck generating composes is updated to use this new timestamp.

I have not tested the migration in any way, so it needs careful review (or tips on how to test it).