Project

General

Profile

action #53771

unstable test: t/ui/15-comments.t in line 102: "got: 'Demo wrote less than a minute ago (last edited less than a minute ago)'" expected: 'Demo wrote less than a minute ago'

Added by okurz over 2 years ago. Updated over 1 year ago.

Status:
Resolved
Priority:
Normal
Assignee:
Category:
Concrete Bugs
Target version:
Start date:
2019-07-03
Due date:
% Done:

0%

Estimated time:
Difficulty:

Description

Observation

./t/ui/15-admin-workers.t ............ ok
        #   Failed test 'heading text'
        #   at ./t/ui/15-comments.t line 102.
        #          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 6.
    #   Failed test 'add'
    #   at ./t/ui/15-comments.t line 132.
    # Looks like you failed 1 test of 4.
#   Failed test 'commenting on parent group overview'
#   at ./t/ui/15-comments.t line 404.
# Looks like you failed 1 test of 13.

Related issues

Related to openQA Project - action #53498: [sporadic] openQA CI tests fail on master in flaky/unstable t/ui/26-jobs_restart.tResolved2019-06-24

Copied 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 over 2 years ago

  • Subject changed from unstable test: t/ui/15-admin-workers.t in line 102: "got: 'Demo wrote less than a minute ago (last edited less than a minute ago)'" expected: 'Demo wrote less than a minute ago' to unstable test: t/ui/15-comments.t in line 102: "got: 'Demo wrote less than a minute ago (last edited less than a minute ago)'" expected: 'Demo wrote less than a minute ago'
  • Status changed from New to In Progress
  • Assignee set to okurz

#2 Updated by okurz over 2 years ago

  • Status changed from In Progress to Workable
  • Assignee deleted (okurz)
for i in {001..100} ;do echo "### $i" && prove t/ui/15-comments.t || break ; done

did not fail. I wonder if this is something related to the database content which is potentially altered by other parallel tests? I hope we can collect more data in the future.

#3 Updated by tinita about 2 years ago

On my machine it always fails, but the failing test changes.

First run:

ok 9 - table properties shown
not ok 10 - still on 99963
#   Failed test 'still on 99963'
#   at t/ui/15-admin-workers.t line 157.
#                   'All Tests
# Job Groups
# Logged in as Demo
# Worker localhost:1
# Host: localhost
# Instance: 1
# Alive: yes
# Websocket connection: Offline
# Seen: about 2 hours ago
# Status: Working
# Properties
# Key Value
# JOBTOKEN token99963
# Previous jobs
# Show
# 10
# 25
# 50
# 100
# entries
# Test Result Finished
# opensuse-13.1-NET-x86_64-Build0091-kde@64bit not yet
# opensuse-Factory-staging_e-x86_64-Build87.5011-minimalx@32bit 0 about an hour ago
# Showing 1 to 2 of 2 entries
# Previous
# 1
# Next
# openQA is licensed GPL-2.0 - Version git-4.5.1528009330.e68ebe2b-bd128366'
#     doesn't match '(?^:Worker status\nJob: 99963)'

Running again:

[debug] 200 OK (0.033591s, 29.770/s)
ok 1 - on workers overview                                                     
ok 2 - localhost:1 do not show delete button                                                          
ok 3 - remotehost:1 do not show delete button     
ok 4 - foo do not show delete button                                                    
ok 5 - online_test do not show delete button                                              
ok 6 - offline worker show delete button                                                                           
ok 7 - localhost:1 shown                                                                                                            
ok 8 - on 99963                                                      
ok 9 - .popover gone                                     
ok 10 - remotehost:1 shown                                    
not ok 11 - working 99961                                                                 
#   Failed test 'working 99961'                                                                   
#   at t/ui/15-admin-workers.t line 123.                                       
#                   ''                                                                   
#     doesn't match '(?^:Worker status\nJob: 99961)'                 
ok 12 - .popover gone                                             
ok 13 - foo shown                                        
ok 14 - worker 5 is broken                                              
ok 15 - reason for brokenness shown                                                                   
1..15                                                                              
# Looks like you failed 1 test of 15.
not ok 6 - worker overview

Additional runs always result in one of the two.

#4 Updated by okurz almost 2 years ago

  • Related to action #53498: [sporadic] openQA CI tests fail on master in flaky/unstable t/ui/26-jobs_restart.t added

#5 Updated by okurz almost 2 years ago

  • Status changed from Workable to Feedback
  • Assignee set to okurz

#6 Updated by cdywan over 1 year ago

  • Target version set to Current Sprint

#7 Updated by okurz over 1 year ago

waiting for #59043 , need to understand if make variables are properly passed into the scope for "stability_test"

#8 Updated by okurz over 1 year ago

  • Status changed from Feedback to Blocked

#9 Updated by okurz over 1 year ago

One more unstable test in https://app.circleci.com/jobs/github/os-autoinst/openQA/16044

[10:04:18] t/ui/21-admin-needles.t .................... 17/? 
    #   Failed test 'getElementAttribute: stale element reference: element is not attached to the page document'
    #   at /home/squamata/project/t/ui/../lib/OpenQA/SeleniumTest.pm line 105.

    #   Failed test 'symlink needle last used module link is correct'
    #   at t/ui/21-admin-needles.t line 172.
    #                   '0'
    #     doesn't match '(?^:admin/needles/9/4)'
    # Looks like you failed 2 tests of 11.
[10:04:18] t/ui/21-admin-needles.t .................... 18/? 
#   Failed test 'dereference symlink when displaying needles info'
#   at t/ui/21-admin-needles.t line 181.

#10 Updated by okurz over 1 year ago

  • Status changed from Blocked to Feedback

I think by now we can continue here independantly . https://app.circleci.com/pipelines/github/os-autoinst/openQA/2441/workflows/e24de55b-6346-4891-8a3d-0506b0e17c71/jobs/22957 shows the original problem again.

I actually managed to reproduce it locally although this was really hard:
A second run of

DIE_ON_FAIL=1 STABILITY_TEST=1 RETRY=200 tools/retry prove -v -l t/ui/15-comments.t

could reproduce it in "Rerun 125 of 200 …" with

        not ok 4 - heading text
        #   Failed test 'heading text'
        #   at t/ui/15-comments.t line 105.
        #          got: 'Demo wrote less than a minute ago (last edited less than a minute ago)'
        #     expected: 'Demo wrote less than a minute ago'
        ok 5 - body text
        ok 6 - anchor matches expected format
        ok 7 - body found via anchor ref
        1..7
        # Looks like you failed 1 test of 7.
    not ok 2 - add
    #   Failed test 'add'
    #   at t/ui/15-comments.t line 136.

one has to keep in mind that this can happen in different top-level tests, e.g. "add" or "remove" regardless.

I think the problem can be fixed with

assets/javascripts/comments.js
@@ -34,6 +34,8 @@ function renderCommentHeading(comment, commentId) {
     abbr_link.prop('class', 'comment-anchor');
     abbr_link.append(renderDate(comment.created));
     heading.append(comment.userName, ' wrote ', abbr_link);
+    // add a margin of 1 to prevent erroneous update detected if off by 1
+    if(comment.updated > (comment.created + 1)) {
-    if(comment.created !== comment.updated) {

as the creation and update time might not be set to exactly the same in the database row.

I wonder though why we seem to have the equivalent code in the perl html template as well:

templates/webapi/comments/comment_row.html.ep
@@ -26,7 +26,7 @@
                         % if($comment) {
                             <%= $user->name %> wrote
                             <a href="#comment-<%= $comment_id %>" class="comment-anchor"><abbr class="timeago" title="<%= $comment->t_created->datetime() %>Z"><%= format_time($comment->t_created) %></abbr></a>
-                            % if ($comment->t_created != $comment->t_updated) {
+                            % if ($comment->t_updated > ($comment->t_created + 1)) {
                                 (last edited <abbr class="timeago" title="<%= $comment->t_updated->datetime() %>Z"><%= format_time($comment->t_updated) %></abbr>)

I will try with the change only in javascript. Maybe we can even delete the part in perl template.

#12 Updated by okurz over 1 year ago

  • Status changed from Feedback to Resolved

PR merged. Given it takes ages to reproduce in master I call this done. We can reopen in case we find it again.

#13 Updated by okurz about 1 year ago

  • Copied 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

Also available in: Atom PDF