Old comments from deleted test case runs appearing in newly created test case runs

[cloudbloat]

I used to have thousands of test case runs with many comments in each... I created simple selenium script, which deleted these test case runs through gui (Login to Kiwi, filter test case runs, click delete, confirm it. Again.).
Deletion was ok but now when I create new test case run, right after it is created with old comments from deleted runs in it....

I am unable to get into database to clear comments, and not sure if it would be enough..

[cloudbloat]

I am now deleting all comments for all test cases using fabricated post requests to https://kiwi.sysct.cz/comments/delete/ .... and will let you know, it it works correctly afterwards...

[atodorov]

I am now deleting all comments for all test cases using fabricated post requests to
https://kiwi.sysct.cz/comments/delete/ .... and will let you know, it it works correctly afterwards...

@cloudbloat any update here?

[cloudbloat]

I am now deleting all comments for all test cases using fabricated post requests to
https://kiwi.sysct.cz/comments/delete/ .... and will let you know, it it works correctly afterwards...

@cloudbloat any update here?

Thanks for interest.

After deleting all comments manually it works perfectly now, IDs are now not overlapping and each new comment has new ID (it doesn't recycle IDs, but increase them). I dont know what caused it, maybe incorrect usage from my side.

[cloudbloat]

So it happened again after restarting our kiwi server...I will try to investigate more and provide more informations....

[cloudbloat]

@atodorov may I ask if there is way to see all existing comments in KIWI mariaDB ? To better investigate problem...(I searched but couldnt find a way)

[atodorov]

$ ./manage.py shell
>>> from django_comments.models import Comment

>>> Comment.objects.all()

>>> for comment in Comment.objects.all():
...     print(comment.submit_date, comment.comment)
... 

[cloudbloat]

So I have deleted all test runs - running and stopped ones, and thanks to your help, I am able to find that there exists still many comments ....
(I tried to "reproduce" with inserting comments to non existing test cases, but it doesnt let me...)

Shouldnt they all be deleted with the test runs ?

(I insert the comments using: rpc_client.exec.TestExecution.add_comment(int(test_case_run_id), str(comment)))

[atodorov]

Can you post the script which creates these comments? Something isn't right here but without a reproducer there's nothing we can do to debug and figure it out.

[cloudbloat]

Thanks for interest... I am inserting comments using Python API (Name: tcms-api, Version: 5.3
; Location: /usr/local/lib/python3.6/dist-packages/tcms_api-5.3-py3.6.egg; using python 3.6.8):

I am using official selenium GRID. all in Docker.

class COMMENT_TEST_CASE_RUN:
    def __init__ (self, test_case_run_id, comment): 
        global errors_string
        self.comment = str(comment)	
        self.test_case_run_id = str(test_case_run_id)
        try:
            rpc_client.exec.TestExecution.add_comment(int(test_case_run_id), str(comment))
        except Exception as e:
            pass (there are some actions which doesnt affect KIWI TCMS - eg "add error line to mongodb")

It may happen more often if I start the same test more times (testcase run endded with state FAILED and I change it to RUNNING from parallel process and add comments again...)...not sure about this yet..but this should be the case.....

It didnt happen few days after restarting Kiwi instance, but today (after about 10 days of usage) it appeared again... Today there are very old comments falling into new test runs - see img:

[atodorov]

Several notes:

1. tcms_api-5.3 is rather old. There are new versions but you should take into account that newer versions are compatible with newer backend versions only. This is all documented but shouldn't matter in your case.

2. TestExecution.add_comment is apparently working since you can see the comments

3. Can you confirm that when your scripts are running they are using test_case_run_id==1038 (later renamed to execution_id) ? In other words, when the above code snippet executes do you see the newly added comment in the web UI?

4. Running scripts(test jobs) in parallel shouldn't matter in this case. True you may have a race condition where the TR or TE status is overwritten but this wouldn't prevent multiple comments from being added. They are just saved into another DB table and later queried from there, so multiple comments would be shown if there have been multiple executions.

5. The fact that you say you are restarting your Kiwi TCMS instance doesn't matter. These things are in the database. Either they are there or they are not.

We need more information here:

0. Version of Kiwi TCMS you are running, DB engine and version.

1. with browser tools inspect the delete comment icon. In the HTML you will notice hidden input fields for object_pk and comment_id. Make a note of them. object_pk should be the same as test_case_run_id. comment_id is the ID of this record in the comments table.

When you see comments, which you think must not be there inspect both of the IDs for them and post the findings here.

2. Your original report says you've first created test cases and then deleted them via the UI. Here comments relationship is not a FK (this is how django-comments works) so comments are not deleted via cascade delete.

The only thing I can imagine that may be happening is that originally you've created many test runs/executions and comments and now after the deletion your TE (TestCaseRun in older versions) objects are being created with the same IDs and these older comments get assigned to them.

I can't reproduce this behavior, i.e. when I delete something the next object is created with an ID which is +1 of the old ID.

Notice: I do see something strage in my exploration. object_pk mattches the case_id instead of the execution id. This is what is shown in the HTML, not sure ATM if it has always been like this or we've broken it somehow. This is why I need you to provide more info.

[cloudbloat]

1. tcms_api-5.3 is rather old. There are new versions but you should take into account that newer versions are compatible with newer backend versions only. This is all documented but shouldn't matter in your case.

OK

2. TestExecution.add_comment is apparently working since you can see the comments

Yes, working fine. Comments are added in 95% cases.

3. Can you confirm that when your scripts are running they are using test_case_run_id==1038 (later renamed to execution_id) ? In other words, when the above code snippet executes do you see the newly added comment in the web UI?

Yes works OK. It really looks like it works until started in parallel, then some comments are being lost. - I will be reproducing today (26.9.) to find out exact state and add debug messages on "add comment" function.

4. Running scripts(test jobs) in parallel shouldn't matter in this case. True you may have a race condition where the TR or TE status is overwritten but this wouldn't prevent multiple comments from being added. They are just saved into another DB table and later queried from there, so multiple comments would be shown if there have been multiple executions.

Paralel execution from one test case run is used only when debugging the test scenario...It is not standard way of usage.

5. The fact that you say you are restarting your Kiwi TCMS instance doesn't matter. These things are in the database. Either they are there or they are not.
   OK :)

Q/A:

1. Version of Kiwi TCMS you are running, DB engine and version.

• Kiwi TCMS - 6.10
• DB engine + version - Server version: 5.5.60-MariaDB MariaDB Server;
• "SELECT PLUGIN_NAME, PLUGIN_VERSION, PLUGIN_TYPE_VERSION, PLUGIN_LIBRARY , PLUGIN_LIBRARY_VERSION, PLUGIN_AUTHOR FROM information_schema.PLUGINS WHERE PLUGIN_NAME = 'innodb';" >> InnoDB - PLUGIN_VERSION: 5.5, PLUGIN_TYPE_VERSION: 50560.0
• "SHOW GLOBAL VARIABLES LIKE 'innodb_ver%';" >> innodb_version | 5.5.59-MariaDB-38.11
• mariadb-server-5.5.60-1.el7_5.x86_64
• mariadb-libs-5.5.60-1.el7_5.x86_64
• mariadb-5.5.60-1.el7_5.x86_64

2. with browser tools inspect the delete comment icon. In the HTML you will notice hidden input fields for object_pk and comment_id. Make a note of them. object_pk should be the same as test_case_run_id. comment_id is the ID of this record in the comments table.

• please see following image:
  

(> The only thing I can imagine that may be happening is that originally you've created many test runs/executions and comments and now after the deletion your TE (TestCaseRun in older versions) objects are being created with the same IDs and these older comments get assigned to them.

• ABSOLUTELY thats it.
• I am always deleting whole test run (even though there may be running some parallel processes working with the test case runs in it. Adding comments/changing state of non existing test case runs are banned, so it shouldnt affect anything, or maybe it does ?)
  )

• Addition:

MariaDB [kiwi]> status

mysql Ver 15.1 Distrib 5.5.60-MariaDB, for Linux (x86_64) using readline 5.1

Connection id: 7273
Current database: kiwi
Current user: kiwi@kiwi_web.kiwi_default
SSL: Not in use
Current pager: stdout
Using outfile: ''
Using delimiter: ;
Server: MariaDB
Server version: 5.5.60-MariaDB MariaDB Server
Protocol version: 10
Connection: db via TCP/IP
Server characterset: latin1
Db characterset: utf8
Client characterset: latin1
Conn. characterset: latin1
TCP port: *hidden :D *
Uptime: 9 days 19 hours 7 min 4 sec

Threads: 1 Questions: 128862 Slow queries: 0 Opens: 65 Flush tables: 2 Open tables: 91 Queries per second avg: 0.152

[cloudbloat]

So now I am able to always reproduce, but cannot find exact steps what causes it, my STR now:

1. Start test case run in more processes (so each process is sole script which autenthicates and connects to xmlrpc, sends comments repeatedly each after 3seconds. Each script runs in Selenium GRID > each script has its own docker instance with own Chrome and IP) >> not all comments are visible in the GUI.

Could you please help me to get response from rpc_client.exec.TestExecution.add_comment(int(test_case_run_id), str(comment)) ? It shows always correct Test Execution ID.... and no Exception

.

Here is my debug script to try with your selenium grid - only remote executor IP:PORT + test_case_run_id should be changed.:

import time
import selenium
import os, sys
from selenium import webdriver
from tcms_api import TCMS
rpc_client = TCMS()

# !!!!
test_case_run_id = 1060
# !!!!

driver = webdriver.Remote(command_executor='http://IP:PORT/wd/hub', desired_capabilities={'browserName': 'chrome'})

class CHANGE_STATUS_TEST_CASE_RUN:
    def __init__ (self, test_case_run_id, status_number): 
        self.status_number = str(status_number)	
        self.test_case_run_id = str(test_case_run_id)
        rpc_client.exec.TestExecution.update(int(test_case_run_id), {'status': int(status_number)})

class COMMENT_TEST_CASE_RUN:
    def __init__ (self, test_case_run_id, comment): 
        global errors_string
        self.comment = str(comment)	
        self.test_case_run_id = str(test_case_run_id)
        print (test_case_run_id)
        try:
            rpc_client.exec.TestExecution.add_comment(int(test_case_run_id), str(comment))
        except Exception as e:
            print ("Cannot add comment because of error: "+str(e))
            pass ### (there are some actions which doesnt affect KIWI TCMS - eg "add error line to mongodb")

try:
    CHANGE_STATUS_TEST_CASE_RUN(test_case_run_id, 2)
    driver.get("https://www.google.com")
    COMMENT_TEST_CASE_RUN(int(test_case_run_id),"STEP 1  DEBUG KIWI TCMS")
    time.sleep(3)
    COMMENT_TEST_CASE_RUN(int(test_case_run_id),"STEP 2  DEBUG KIWI TCMS")
    time.sleep(3)
    COMMENT_TEST_CASE_RUN(int(test_case_run_id),"STEP 3  DEBUG KIWI TCMS")
    time.sleep(3)
    COMMENT_TEST_CASE_RUN(int(test_case_run_id),"STEP 4  DEBUG KIWI TCMS")
    time.sleep(3)
    COMMENT_TEST_CASE_RUN(int(test_case_run_id),"STEP 5  DEBUG KIWI TCMS")
    time.sleep(3)
    COMMENT_TEST_CASE_RUN(int(test_case_run_id),"STEP 6  DEBUG KIWI TCMS")
    time.sleep(3)
    COMMENT_TEST_CASE_RUN(int(test_case_run_id),"STEP 7  DEBUG KIWI TCMS")
    time.sleep(3)
    COMMENT_TEST_CASE_RUN(int(test_case_run_id),"STEP 8  DEBUG KIWI TCMS")
    time.sleep(3)
    CHANGE_STATUS_TEST_CASE_RUN(test_case_run_id, 6)
    COMMENT_TEST_CASE_RUN(int(test_case_run_id),"STEP 9  DEBUG KIWI TCMS")
    time.sleep(3)
    COMMENT_TEST_CASE_RUN(int(test_case_run_id),"STEP 10  DEBUG KIWI TCMS")
    time.sleep(3)
    COMMENT_TEST_CASE_RUN(int(test_case_run_id),"STEP 11  DEBUG KIWI TCMS")
    time.sleep(3)
    COMMENT_TEST_CASE_RUN(int(test_case_run_id),"STEP 12  DEBUG KIWI TCMS")
    time.sleep(3)
    COMMENT_TEST_CASE_RUN(int(test_case_run_id),"STEP 13  DEBUG KIWI TCMS")
    time.sleep(3)
    COMMENT_TEST_CASE_RUN(int(test_case_run_id),"STEP 14  DEBUG KIWI TCMS")
    time.sleep(3)
    COMMENT_TEST_CASE_RUN(int(test_case_run_id),"STEP 15  DEBUG KIWI TCMS")
    time.sleep(3)
    COMMENT_TEST_CASE_RUN(int(test_case_run_id),"STEP 16  DEBUG KIWI TCMS")
    time.sleep(3)
    CHANGE_STATUS_TEST_CASE_RUN(test_case_run_id, 5)	
    COMMENT_TEST_CASE_RUN(int(test_case_run_id),"STEP 17  DEBUG KIWI TCMS")
    time.sleep(3)
    COMMENT_TEST_CASE_RUN(int(test_case_run_id),"STEP 18  DEBUG KIWI TCMS")
    time.sleep(3)
    COMMENT_TEST_CASE_RUN(int(test_case_run_id),"STEP 19  DEBUG KIWI TCMS")
    time.sleep(3)
    COMMENT_TEST_CASE_RUN(int(test_case_run_id),"STEP 20  DEBUG KIWI TCMS")
    COMMENT_TEST_CASE_RUN(test_case_run_id, "Test was finished correctly.")
    sys.exit()    
except Exception as e:
    CHANGE_STATUS_TEST_CASE_RUN(test_case_run_id, 5)	
    print ("Il y a erreur "+str(e))
    sys.exit()

• all you need is to start this script in parallel (I used 6 instances=6times start) with your Selenium GRID. Of course you may play with it to reproduce - like manually set to finish the whole RUN and deleting it while all tests are not finished.
  In the end you can count the comments in selected test execution, eg (are there "number of starts" * "STEP 1 DEBUG KIWI TCMS" comments ?)

but in the end, isnt the problem this?:

Your original report says you've first created test cases and then deleted them via the UI. Here comments relationship is not a FK (this is how django-comments works) so comments are not deleted via cascade delete.
- doesnt this mean, that if I delete test runs from KIWI TCMS GUI - it doesnt delete comments from its test executions ?

[atodorov]

There are a number of issues here:

1. The wrong object_pk hidden field value in HTML templates. This will actually be removed b/c we don't really use it when deleting comments. Only comment_id is used.

2. Comments not actually deleted but marked as hidden. We'll now call a .delete() on the query set and actually remove these objects from the DB

3. Comments not removed when the object they point to is removed. This will be resolved via pre-delete signal b/c we already have this machinery in place and b/c we can't reliably modify django_comments to turn the object_pk field into a ForeignKey relationship (b/c it points to multiple other tables). Again this will be a permanent delete from the DB.

1-3 will be solved by #1220 which will also close this issue.

4. As stated earlier you may have had a situation where PK values have been recycled. That is an existing object has been deleted, then a new one created with the same ID which manifested as old comments being shown.

We still don't have enough information to figure out why this was happening in the first place. The only pointers I can give you is to check how transactions on your MariaDB have been configured. Maybe also look at sequences and auto-increment (LAST_INSERT_ID) settings. I can't reproduce and it's outside the scope of this issue anyway.

With the merging of deletion changes even if IDs are recycled the problem of seeing older comments should be less prominent. Will be non existent if you manually remove all comments for which object_pk doesn't point anywhere.

5. Possible issues with parallel script execution : I don't see issues with adding comments in parallel per se. Order of comments & TE statuses may be misaligned due to timing (race conditions) but this is the nature of manipulating objects in parallel. Adding comments is an insert operation so nothing should be lost. If RPC didn't report an exception then there wasn't any when performing the database operation.

In your last comment you also state

play with it to reproduce - like ... deleting it while all tests are not finished

If you have operations pending towards an existing object and you delete that same object from the DB then the behavior is undefined. Transactional settings on your DB engine will likely have effect here. This may or may not be a contributing factor to issue 4). In any case I don't think there's something we can do about it on our end.

If you continue to see 4) and 5) please collect more debugging information & steps to reproduce and open another issue.

[cloudbloat]

Fix Confirmed - Thank you very much !!! Now it works without described problems :)