Not exiting final thread #991

k0mand1r · 2024-04-02T21:39:06Z

SQ CE: 10.1
sonar-tools: 2.9

Seems like the application is not fully closing all threads. sonar-housekeeper has been stuck for 1hr like this.
The command was running for 1hr, before getting stuck.

sonar-housekeeper -t $SONAR_TOKEN -u $SONAR_HOST_URL -v DEBUG -P 180 --mode delete

2024-04-02 22:53:49,416 | sonar-tools | DEBUG   | ProjectAudit6   | GET: TOKEN@SONARQUBE/api/ce/activity?status=SUCCESS%2CPENDING%2CIN_PROGRESS%2CFAILED%2CCANCELED&additionalFields=warnings&onlyCurrents=true&component=APPLICATION
2024-04-02 22:53:49,541 | sonar-tools | DEBUG   | ProjectAudit6   | Auditing background task 'AY2**********'
2024-04-02 22:53:49,541 | sonar-tools | DEBUG   | ProjectAudit6   | Last background task of project 'APPLICATION' has no scanner context, can't audit it
2024-04-02 22:53:49,541 | sonar-tools | WARNING | ProjectAudit6   | project 'APPLICATION' last analysis had the following warnings: The properties 'sonar.login' and 'sonar.password' are deprecated and will be removed in the future. Please pass a token with the 'sonar.token' property instead.
2024-04-02 22:53:49,541 | sonar-tools | DEBUG   | ProjectAudit6   | Last bg task of project 'APPLICATION' has status SUCCESS...
2024-04-02 22:53:49,542 | sonar-tools | INFO    | ProjectAudit6   | Community edition, skipping binding validation...
2024-04-02 22:53:49,542 | sonar-tools | DEBUG   | ProjectAudit6   | project 'APPLICATION' audit done
2024-04-02 22:53:49,542 | sonar-tools | DEBUG   | ProjectAudit6   | Queue empty, exiting thread

Any tips on how to solve this?

The text was updated successfully, but these errors were encountered:

okorach · 2024-04-03T11:43:31Z

Hello @k0mand1r,
Thanks for reporting this.
Indeed there seems to be a thread synchronization problem.
You can stop the housekeeper with [Ctrl-C]

I am surprised that you have no stack trace in the logs. Did you indeed capture the stderr too?
Also I suspect that the problem happens much earlier in the logs, the last few lines are not sufficient, please send the entire logs from start to stuck housekeeper.
As a temp workaround for you might be to limit the number of thread to 1. By default sonar-housekeeper runs with 8 threads to perform tasks in parallel. 1 single thread may be longer but is less likely to cause thread sync problems. That could also better isolate the part that causes the problem (logs may stop when the problem happens)

sonar-housekeeper -t $SONAR_TOKEN -u $SONAR_HOST_URL -v DEBUG -P 180 --mode delete --threads 1

k0mand1r · 2024-04-03T12:29:24Z

Thank you for your reply. I did not capture stderr. I can rerun with capturing stderr to a file.

do you mean to send the entire sonar-tools.log? will have to anonimize a lot of data.
Was going to try the run with --threads 1 today, thanks for also proposing this workaround.

k0mand1r · 2024-04-03T13:53:37Z

This was the error when running with 8 threads this morning. It's trying to delete a component which has previously been deleted in the MainThread. It seems based on this behaviour that:

this APPLICATION has been put in queue multiple times?
- the search is being threaded even though --threads 1 is set?
- the threaded search doesn't account for network delays and thus does not check if another thread has already collected it?
there is no check when creating the initial queue for duplicate endpoints/project/components.
the behaviour is by design (check if deleted) and the error handling contains a bug?

threaded search with --threads 1
Does this collect all information 3x?

2024-04-03 15:04:44,559 | sonar-tools | DEBUG   | MainThread      | Starting Project search thread 0
2024-04-03 15:04:44,559 | sonar-tools | DEBUG   | Search0         | Threaded search: API = projects/search params = {'qualifiers': 'TRK', 'ps': 500, 'p': 1}
2024-04-03 15:04:44,559 | sonar-tools | DEBUG   | MainThread      | Starting Project search thread 1
2024-04-03 15:04:44,560 | sonar-tools | DEBUG   | Search0         | GET: TOKEN@SONARQUBE/api/projects/search?qualifiers=TRK&ps=500&p=2
2024-04-03 15:04:44,560 | sonar-tools | DEBUG   | Search1         | Threaded search: API = projects/search params = {'qualifiers': 'TRK', 'ps': 500, 'p': 1}
2024-04-03 15:04:44,560 | sonar-tools | DEBUG   | Search1         | GET: TOKEN@SONARQUBE/api/projects/search?qualifiers=TRK&ps=500&p=3
2024-04-03 15:04:44,561 | sonar-tools | DEBUG   | MainThread      | Starting Project search thread 2
2024-04-03 15:04:44,561 | sonar-tools | DEBUG   | Search2         | Threaded search: API = projects/search params = {'qualifiers': 'TRK', 'ps': 500, 'p': 1}
2024-04-03 15:04:44,561 | sonar-tools | DEBUG   | Search2         | GET: TOKEN@SONARQUBE/api/projects/search?qualifiers=TRK&ps=500&p=4
2024-04-03 15:04:44,561 | sonar-tools | DEBUG   | MainThread      | Starting Project search thread 3
2024-04-03 15:04:44,562 | sonar-tools | DEBUG   | MainThread      | Starting Project search thread 4
2024-04-03 15:04:44,563 | sonar-tools | DEBUG   | MainThread      | Starting Project search thread 5
2024-04-03 15:04:44,563 | sonar-tools | DEBUG   | MainThread      | Starting Project search thread 6
2024-04-03 15:04:44,563 | sonar-tools | DEBUG   | MainThread      | Starting Project search thread 7

8 threads

2024-04-03 | sonar-tools | DEBUG   | MainThread      | Getting measures with {'component': 'APPLICATION', 'metricKeys': 'ncloc'}
2024-04-03 | sonar-tools | DEBUG   | MainThread      | GET: TOKEN@SONARQUBE/api/measures/component?component=APPLICATION&metricKeys=ncloc
2024-04-03 | sonar-tools | INFO    | MainThread      | Deleting project 'APPLICATION', 1069 LoC
2024-04-03 | sonar-tools | DEBUG   | MainThread      | Getting measures with {'component': 'APPLICATION', 'metricKeys': 'ncloc'}
2024-04-03 | sonar-tools | DEBUG   | MainThread      | GET: TOKEN@SONARQUBE/api/measures/component?component=APPLICATION&metricKeys=ncloc
2024-04-03 | sonar-tools | INFO    | MainThread      | Deleting project 'APPLICATION', name 'APPLICATION' with 1069 LoCs
2024-04-03 | sonar-tools | INFO    | MainThread      | Deleting project 'APPLICATION'
2024-04-03 | sonar-tools | DEBUG   | MainThread      | POST: TOKEN@SONARQUBE/api/projects/delete?project=APPLICATION
2024-04-03 | sonar-tools | INFO    | MainThread      | Successfully deleted project 'APPLICATION'
2024-04-03 | sonar-tools | INFO    | MainThread      | Successfully deleted project 'APPLICATION' - 1069 LoCs
2024-04-03 | sonar-tools | DEBUG   | MainThread      | Getting measures with {'component': 'APPLICATION', 'metricKeys': 'ncloc'}
2024-04-03 | sonar-tools | DEBUG   | MainThread      | GET: TOKEN@SONARQUBE/api/measures/component?component=APPLICATION&metricKeys=ncloc
2024-04-03 | sonar-tools | ERROR   | MainThread      | GET Error: TOKEN@SONARQUBE/api/measures/component?component=APPLICATION&metricKeys=ncloc HTTP status code 404

1 thread

2024-04-03 15:31:08,006 | sonar-tools | DEBUG   | MainThread      | Getting measures with {'component': 'APPLICATION', 'metricKeys': 'ncloc'}
2024-04-03 15:31:08,006 | sonar-tools | DEBUG   | MainThread      | GET: TOKEN@SONARQUBE/api/measures/component?component=APPLICATION&metricKeys=ncloc
2024-04-03 15:31:08,118 | sonar-tools | INFO    | MainThread      | Deleting project 'APPLICATION', 759 LoC
2024-04-03 15:31:08,118 | sonar-tools | DEBUG   | MainThread      | Getting measures with {'component': 'APPLICATION', 'metricKeys': 'ncloc'}
2024-04-03 15:31:08,118 | sonar-tools | DEBUG   | MainThread      | GET: TOKEN@SONARQUBE/api/measures/component?component=APPLICATION&metricKeys=ncloc
2024-04-03 15:31:08,238 | sonar-tools | INFO    | MainThread      | Deleting project 'APPLICATION', name 'APPLICATION' with 759 LoCs
2024-04-03 15:31:08,239 | sonar-tools | INFO    | MainThread      | Deleting project 'APPLICATION'
2024-04-03 15:31:08,239 | sonar-tools | DEBUG   | MainThread      | POST: TOKEN@SONARQUBE/api/projects/delete?project=APPLICATION
2024-04-03 15:31:10,877 | sonar-tools | INFO    | MainThread      | Successfully deleted project 'APPLICATION'
2024-04-03 15:31:10,878 | sonar-tools | INFO    | MainThread      | Successfully deleted project 'APPLICATION' - 759 LoCs
2024-04-03 15:31:10,879 | sonar-tools | DEBUG   | MainThread      | Getting measures with {'component': 'APPLICATION', 'metricKeys': 'ncloc'}
2024-04-03 15:31:10,879 | sonar-tools | DEBUG   | MainThread      | GET: TOKEN@SONARQUBE/api/measures/component?component=APPLICATION&metricKeys=ncloc
2024-04-03 15:31:10,982 | sonar-tools | ERROR   | MainThread      | GET Error: TOKEN@SONARQUBE/api/measures/component?component=APPLICATION&metricKeys=ncloc HTTP status code 404

stacktrace --threads 1

Traceback (most recent call last):
  File "/DIR/.venv/bin/sonar-housekeeper", line 8, in <module>
    sys.exit(main())
  File "/DIR/.venv/lib/python3.9/site-packages/tools/housekeeper.py", line 224, in main
    (deleted_proj, deleted_loc, deleted_branches, deleted_prs, revoked_tokens) = _delete_objects(problems, mode)
  File "/DIR/.venv/lib/python3.9/site-packages/tools/housekeeper.py", line 171, in _delete_objects
    loc = int(obj.get_measure("ncloc", fallback="0"))
  File "/DIR/.venv/lib/python3.9/site-packages/sonar/components.py", line 145, in get_measure
    meas = self.get_measures(metric)
  File "/DIR/.venv/lib/python3.9/site-packages/sonar/projects/projects.py", line 253, in get_measures
    m = measures.get(self, metrics_list)
  File "/DIR/.venv/lib/python3.9/site-packages/sonar/measures.py", line 125, in get
    data = json.loads(concerned_object.endpoint.get(Measure.API_READ, params={**kwargs, **params}).text)
  File "/DIR/.venv/lib/python3.9/site-packages/sonar/platform.py", line 180, in get
    raise e
  File "/DIR/.venv/lib/python3.9/site-packages/sonar/platform.py", line 171, in get
    r.raise_for_status()
  File "/DIR/.venv/lib/python3.9/site-packages/requests/models.py", line 1021, in raise_for_status
    raise HTTPError(http_error_msg, response=self)
requests.exceptions.HTTPError: 404 Client Error:  for url: SONARQUBE/api/measures/component?component=APPLICATION&metricKeys=ncloc

okorach · 2024-04-07T16:00:49Z

Thanks for all this data @k0mand1r. That helps a lot

wrt to your points:

Does this collect all information 3x?

No. It's just that the API is paginated so to get all the objects we need to iterate through several pages (parameter p in the api/projects/search API call)

there is no check when creating the initial queue for duplicate endpoints/project/components.

Yes. That seems to be the bug, but I puzzled how there can be a duplicate on the list of objects to delete since the tool iterates only once on all the objects. I will investigate.
I will also handle the case of object not found (404), since anyway this could happen that an object is deleted (eg in the UI) while housekeeper is running. The exception should be caught and gracefully handled.

okorach · 2024-04-07T16:26:13Z

Ok. I think I understood.
The tool does not delete the project twice, or the project is not twice in the list of objects to delete.
It's just that accidentally, to count the number of LoC deleted, we request the number of project LoC once more after the project is deleted, and therefore the api/measures/component?component=APPLICATION&metricKeys=ncloc ends with a 404.
I'll fix that soon

okorach · 2024-04-08T14:58:00Z

Hello @k0mand1r,

After investigation on my side, I never managed to have the same project added twice to the list so I am not sure how it happens on your side (Maybe if you have a project and a project branch that meet the purge criteria).
Anyhow, I made sonar-housekeeper robust to the eventuality of having the same project multiple time in the list of objects.
Any subsequent attempt to (re)delete the same project is gracefully handled now, so sonar-housekeeper should never stall.
I attach a preview of sonar-tools 2.10. If you can confirm that your problem is solved, that would be great.
sonar_tools-2.10-py3-none-any.whl.zip
Install with:

unzip sonar_tools-2.10-py3-none-any.whl.zip
pip uninstall sonar-tools
pip install sonar_tools-2.10-py3-none-any.whl

Let me know.

k0mand1r · 2024-05-22T11:33:14Z

Hi @okorach,

Thank you for your reply. I was away for a bit.
Will try test it this week or start of next week and come back to you on it.

Kind regards,

okorach added this to the 2.10 milestone Apr 3, 2024

okorach added the bug label Apr 3, 2024

okorach linked a pull request Apr 7, 2024 that will close this issue

Raise ObjectNotFound when getting measure of non existing object #993

Merged

okorach closed this as completed in #993 Apr 7, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Not exiting final thread #991

Not exiting final thread #991

k0mand1r commented Apr 2, 2024

okorach commented Apr 3, 2024 •

edited

Loading

k0mand1r commented Apr 3, 2024 •

edited

Loading

k0mand1r commented Apr 3, 2024 •

edited

Loading

okorach commented Apr 7, 2024 •

edited

Loading

okorach commented Apr 7, 2024

okorach commented Apr 8, 2024

k0mand1r commented May 22, 2024

Not exiting final thread #991

Not exiting final thread #991

Comments

k0mand1r commented Apr 2, 2024

okorach commented Apr 3, 2024 • edited Loading

k0mand1r commented Apr 3, 2024 • edited Loading

k0mand1r commented Apr 3, 2024 • edited Loading

okorach commented Apr 7, 2024 • edited Loading

okorach commented Apr 7, 2024

okorach commented Apr 8, 2024

k0mand1r commented May 22, 2024

okorach commented Apr 3, 2024 •

edited

Loading

k0mand1r commented Apr 3, 2024 •

edited

Loading

k0mand1r commented Apr 3, 2024 •

edited

Loading

okorach commented Apr 7, 2024 •

edited

Loading