action #111542
closed[sporadic] openQA test t/ui/15-comments.t fails in 'heading text' size:M
0%
Description
Observation¶
[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
Updated by okurz over 2 years 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
Updated by mkittler over 2 years 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
Updated by mkittler over 2 years 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.
Updated by mkittler over 2 years 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.
Updated by mkittler over 2 years 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
Updated by mkittler over 2 years 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.
Updated by okurz over 1 year ago
- Related to action #128153: [sporadic] typing issue in comments UI test t/15-comments.t size:M added
Updated by okurz over 1 year ago
- Related to action #129946: [tools][ci][ui] Randomly failing t/ui/15-comments.t added