Project

General

Profile

action #111542

[sporadic] openQA test t/ui/15-comments.t fails in 'heading text' size:M

Added by okurz 3 months ago. Updated 2 months ago.

Status:
Resolved
Priority:
High
Assignee:
Category:
Concrete Bugs
Target version:
Start date:
2022-05-24
Due date:
% Done:

0%

Estimated time:
Difficulty:

Description

Observation

https://app.circleci.com/pipelines/github/os-autoinst/openQA/9642/workflows/d48bcdfe-9b1e-47a1-bc80-53b05167be46/jobs/90997?invite=true#step-107-89 shows

[10:40:27] t/ui/15-comments.t ......................... 1/? 
        #   Failed test 'heading text'
        #   at t/ui/15-comments.t line 89.
        #          got: 'Demo wrote less than a minute ago (last edited less than a minute ago)'
        #     expected: 'Demo wrote less than a minute ago'
        # Looks like you failed 1 test of 12.

    #   Failed test 'remove'
    #   at t/ui/15-comments.t line 176.
    # Looks like you failed 1 test of 4.
[10:40:27] t/ui/15-comments.t ......................... 8/? 
#   Failed test 'commenting in the group overview'
#   at t/ui/15-comments.t line 181.
[10:40:27] t/ui/15-comments.t ......................... 9/? [10:40:27] t/ui/15-comments.t ......................... 10/? [10:40:27] t/ui/15-comments.t ......................... 11/? [10:40:27] t/ui/15-comments.t ......................... 12/? [10:40:27] t/ui/15-comments.t ......................... 14/? # Looks like you failed 1 test of 14.
                                                              [10:40:27] t/ui/15-comments.t ......................... Dubious, test returned 1 (wstat 256, 0x100)
Failed 1/14 subtests

Acceptance criteria

  • AC1: The test no longer fails (even sporadically)

Suggestions

  • Check for ambiguous CSS selectors
  • Check for race conditions
  • Check for inaccuracies (maybe a comment is considered edited if t_created and t_updated differ and that might be also due to rounding)
  • Use headful mode to watch what's actually going on

Related issues

Related to openQA Project - action #72319: unstable test: t/ui/15-comments.t "got: 'Demo wrote less than a minute ago (last edited less than a minute ago)'" expected: 'Demo wrote less than a minute ago' (2nd try)Resolved2020-10-14

History

#1 Updated by okurz 3 months ago

  • Related to action #72319: unstable test: t/ui/15-comments.t "got: 'Demo wrote less than a minute ago (last edited less than a minute ago)'" expected: 'Demo wrote less than a minute ago' (2nd try) added

#2 Updated by mkittler 3 months ago

  • Subject changed from [sporadic] openQA test t/ui/15-comments.t fails in 'heading text' to [sporadic] openQA test t/ui/15-comments.t fails in 'heading text' size:M
  • Description updated (diff)
  • Status changed from New to Workable

#3 Updated by mkittler 3 months ago

  • Assignee set to mkittler

#4 Updated by mkittler 3 months ago

  • Status changed from Workable to In Progress

PR for fixing the workaround that is already in place: https://github.com/os-autoinst/openQA/pull/4673

Not sure whether we can fix the real issue. I'll have a look how those timestamps are initialized.

#5 Updated by mkittler 3 months ago

The insertion ends up being the following SQL:

    <- prepare_cached('INSERT INTO comments ( job_id, t_created, t_updated, text, user_id) VALUES ( ?, ?, ?, ?, ? ) RETURNING id', HASH(0x5632f072e6f0), ...)= ( DBI::st=HASH(0x5632f1dc41b0) ) [1 items] at DBI.pm line 1972
    <- bind_param(1, 2820, ...)= ( 1 ) [1 items] at DBI.pm line 2013
    <- bind_param(2, '2022-05-25 12:39:10', ...)= ( 1 ) [1 items] at DBI.pm line 2013
    <- bind_param(3, '2022-05-25 12:39:10', ...)= ( 1 ) [1 items] at DBI.pm line 2013
    <- bind_param(4, "bar", ...)= ( 1 ) [1 items] at DBI.pm line 2013
    <- bind_param(5, 2, ...)= ( 1 ) [1 items] at DBI.pm line 2013

So the timestamps are already computed on the Perl-side. The relevant Perl module is DBIx::Class::Timestamps (in our repository but utilizing https://metacpan.org/pod/DBIx::Class::InflateColumn::DateTime, https://metacpan.org/pod/DBIx::Class::TimeStamp and https://metacpan.org/pod/DBIx::Class::DynamicDefault). Judging by the code I'd say the race condition isn't a surprise:

sub add_timestamps {
    my $self = shift;

    $self->load_components(qw(InflateColumn::DateTime DynamicDefault));

    $self->add_columns(
        t_created => {
            data_type => 'timestamp',
            dynamic_default_on_create => 'now'
        },
        t_updated => {
            data_type => 'timestamp',
            dynamic_default_on_create => 'now',
            dynamic_default_on_update => 'now'
        },
    );
}

sub now {
    DateTime->now(time_zone => 'UTC');
}

The function specified via dynamic_default_on_create is most likely called individually per column and obviously sub now might return different values. So I suppose a real fix needed to be done in https://metacpan.org/dist/DBIx-Class-DynamicDefault/source/lib/DBIx/Class/DynamicDefault.pm.

#6 Updated by mkittler 3 months ago

  • Status changed from In Progress to Feedback

I suppose it'll be hard to improve https://metacpan.org/dist/DBIx-Class-DynamicDefault/source/lib/DBIx/Class/DynamicDefault.pm because it is designed to allow setting defaults on column-level. It is generally also ok as we don't really care if those timestamps are off. So I've created a fix for comments specifically: https://github.com/os-autoinst/openQA/pull/4674

#7 Updated by mkittler 2 months ago

  • Status changed from Feedback to Resolved

The PR https://github.com/os-autoinst/openQA/pull/4674 has been merged and deployed. It was only a sporadic issue but considering I could understand the underlying problem I'm confident that the PR fixes it.

Also available in: Atom PDF