API: Exceptions swallowed by custom exception handler

[QuentinVsm]

Slack us first!
The easiest and fastest way to help you is via Slack. There's a free and easy signup to join our #defectdojo channel in the OWASP Slack workspace: Get Access.
If you're confident you've found a bug, or are allergic to Slack, you can submit an issue anyway.

Be informative
We were working on the 2.1.0 release, so we update our defect dojo to 2.2.0. And the bug still happens.
In 2.2.0 the we can't see the full trace log.

Bug description
When trying to add a finding to a test via API this generate an Internal Server Error 500.
The test can belong to an active or closed Engagement, the bug works in the same way.
Note : the bug didn't happen with the web UI.

Steps to reproduce
Steps to reproduce the behavior:

1. Go to [defect-dojo url]/api/v2/doc/
2. Click on 'findings' -> 'POST findings_create'
3. Correctly fill the form (add a valid test id, valid user id, make active and verified true and all other required parameters)
4. Click on 'execute'
5. See internal error 500

Here is an example of what you can enter in the form (of course you need to change test and user id) :
{
"test": ,
"found_by": [

],
"title": "Fidings",
"date": "2021-09-01",
"severity": "string",
"description": "string",
"active": true,
"verified": true,
"numerical_severity": "s4"
}

Expected behavior
I expected 201 code with a json that represent the just created findings

Deployment method (select with an X)

• [X ] Docker
• Kubernetes
• GoDojo
• setup.bash / legacy-setup.bash

Environment information

• Operating System: Centos 7
• DefectDojo Commit Message: 00b4257

Console logs (optional)
Here is the logs with the 2.1.0 version :

uwsgi_1         | [01/Sep/2021 08:12:59] ERROR [django.request:224] Internal Server Error: /api/v2/findings/
uwsgi_1         | Traceback (most recent call last):
uwsgi_1         |   File "/usr/local/lib/python3.8/site-packages/django/core/handlers/exception.py", line 47, in inner
uwsgi_1         |     response = get_response(request)
uwsgi_1         |   File "/usr/local/lib/python3.8/site-packages/django/core/handlers/base.py", line 181, in _get_response
uwsgi_1         |     response = wrapped_callback(request, *callback_args, **callback_kwargs)
uwsgi_1         |   File "/usr/local/lib/python3.8/site-packages/django/views/decorators/csrf.py", line 54, in wrapped_view
uwsgi_1         |     return view_func(*args, **kwargs)
uwsgi_1         |   File "/usr/local/lib/python3.8/site-packages/rest_framework/viewsets.py", line 125, in view
uwsgi_1         |     return self.dispatch(request, *args, **kwargs)
uwsgi_1         |   File "/usr/local/lib/python3.8/site-packages/rest_framework/views.py", line 509, in dispatch
uwsgi_1         |     response = self.handle_exception(exc)
uwsgi_1         |   File "/usr/local/lib/python3.8/site-packages/rest_framework/views.py", line 469, in handle_exception
uwsgi_1         |     self.raise_uncaught_exception(exc)
uwsgi_1         |   File "/usr/local/lib/python3.8/site-packages/rest_framework/views.py", line 480, in raise_uncaught_exception
uwsgi_1         |     raise exc
uwsgi_1         |   File "/usr/local/lib/python3.8/site-packages/rest_framework/views.py", line 506, in dispatch
uwsgi_1         |     response = handler(request, *args, **kwargs)
uwsgi_1         |   File "/usr/local/lib/python3.8/site-packages/rest_framework/mixins.py", line 18, in create
uwsgi_1         |     serializer.is_valid(raise_exception=True)
uwsgi_1         |   File "/usr/local/lib/python3.8/site-packages/rest_framework/serializers.py", line 220, in is_valid
uwsgi_1         |     self._validated_data = self.run_validation(self.initial_data)
uwsgi_1         |   File "/usr/local/lib/python3.8/site-packages/rest_framework/serializers.py", line 422, in run_validation
uwsgi_1         |     value = self.validate(value)
uwsgi_1         |   File "/app/./dojo/api_v2/serializers.py", line 1078, in validate
uwsgi_1         |     if ((data['active'] or data['verified']) and data['duplicate']):
uwsgi_1         | KeyError: 'active'
uwsgi_1         | ERROR:django.request:Internal Server Error: /api/v2/findings/
uwsgi_1         | Traceback (most recent call last):
uwsgi_1         |   File "/usr/local/lib/python3.8/site-packages/django/core/handlers/exception.py", line 47, in inner
uwsgi_1         |     response = get_response(request)
uwsgi_1         |   File "/usr/local/lib/python3.8/site-packages/django/core/handlers/base.py", line 181, in _get_response
uwsgi_1         |     response = wrapped_callback(request, *callback_args, **callback_kwargs)
uwsgi_1         |   File "/usr/local/lib/python3.8/site-packages/django/views/decorators/csrf.py", line 54, in wrapped_view
uwsgi_1         |     return view_func(*args, **kwargs)
uwsgi_1         |   File "/usr/local/lib/python3.8/site-packages/rest_framework/viewsets.py", line 125, in view
uwsgi_1         |     return self.dispatch(request, *args, **kwargs)
uwsgi_1         |   File "/usr/local/lib/python3.8/site-packages/rest_framework/views.py", line 509, in dispatch
uwsgi_1         |     response = self.handle_exception(exc)
uwsgi_1         |   File "/usr/local/lib/python3.8/site-packages/rest_framework/views.py", line 469, in handle_exception
uwsgi_1         |     self.raise_uncaught_exception(exc)
uwsgi_1         |   File "/usr/local/lib/python3.8/site-packages/rest_framework/views.py", line 480, in raise_uncaught_exception
uwsgi_1         |     raise exc
uwsgi_1         |   File "/usr/local/lib/python3.8/site-packages/rest_framework/views.py", line 506, in dispatch
uwsgi_1         |     response = handler(request, *args, **kwargs)
uwsgi_1         |   File "/usr/local/lib/python3.8/site-packages/rest_framework/mixins.py", line 18, in create
uwsgi_1         |     serializer.is_valid(raise_exception=True)
uwsgi_1         |   File "/usr/local/lib/python3.8/site-packages/rest_framework/serializers.py", line 220, in is_valid
uwsgi_1         |     self._validated_data = self.run_validation(self.initial_data)
uwsgi_1         |   File "/usr/local/lib/python3.8/site-packages/rest_framework/serializers.py", line 422, in run_validation
uwsgi_1         |     value = self.validate(value)
uwsgi_1         |   File "/app/./dojo/api_v2/serializers.py", line 1078, in validate
uwsgi_1         |     if ((data['active'] or data['verified']) and data['duplicate']):
uwsgi_1         | KeyError: 'active'

Note : I confirme that the sended request contain {'active' : true, 'verified': true, ...}

for the 2.2.0 release :

uwsgi_1         | [01/Sep/2021 08:49:47] WARNING [django.request:224] Bad Request: /api/v2/findings/
uwsgi_1         | WARNING:django.request:Bad Request: /api/v2/findings/

Additional context (optional)
Here is something that change with the 2.2.0 release, i don't know if there is any link but this is the log at the start of the app :
initializer_1 | Apply all migrations: admin, auditlog, auth, authtoken, contenttypes, django_celery_results, dojo, sessions, sites, social_django, tagging, watson
initializer_1 | Running migrations:
initializer_1 | Traceback (most recent call last):
initializer_1 | File "/usr/local/lib/python3.8/site-packages/django/db/backends/utils.py", line 84, in _execute
initializer_1 | return self.cursor.execute(sql, params)
initializer_1 | File "/usr/local/lib/python3.8/site-packages/django/db/backends/mysql/base.py", line 73, in execute
initializer_1 | return self.cursor.execute(query, args)
initializer_1 | File "/usr/local/lib/python3.8/site-packages/MySQLdb/cursors.py", line 206, in execute
initializer_1 | res = self._query(query)
initializer_1 | File "/usr/local/lib/python3.8/site-packages/MySQLdb/cursors.py", line 319, in _query
initializer_1 | db.query(q)
initializer_1 | File "/usr/local/lib/python3.8/site-packages/MySQLdb/connections.py", line 259, in query
initializer_1 | _mysql.connection.query(self, query)
initializer_1 | MySQLdb._exceptions.OperationalError: (1060, "Duplicate column name 'sonarqube_config_id'")
initializer_1 |
initializer_1 | The above exception was the direct cause of the following exception:
initializer_1 |
initializer_1 | Traceback (most recent call last):
initializer_1 | File "manage.py", line 11, in
initializer_1 | execute_from_command_line(sys.argv)
initializer_1 | File "/usr/local/lib/python3.8/site-packages/django/core/management/init.py", line 401, in execute_from_command_line
initializer_1 | utility.execute()
initializer_1 | File "/usr/local/lib/python3.8/site-packages/django/core/management/init.py", line 395, in execute
initializer_1 | self.fetch_command(subcommand).run_from_argv(self.argv)
initializer_1 | File "/usr/local/lib/python3.8/site-packages/django/core/management/base.py", line 330, in run_from_argv
initializer_1 | self.execute(*args, **cmd_options)
initializer_1 | File "/usr/local/lib/python3.8/site-packages/django/core/management/base.py", line 371, in execute
initializer_1 | output = self.handle(*args, **options)
initializer_1 | File "/usr/local/lib/python3.8/site-packages/django/core/management/base.py", line 85, in wrapped
initializer_1 | res = handle_func(*args, **kwargs)
initializer_1 | File "/usr/local/lib/python3.8/site-packages/django/core/management/commands/migrate.py", line 243, in handle
initializer_1 | post_migrate_state = executor.migrate(
initializer_1 | File "/usr/local/lib/python3.8/site-packages/django/db/migrations/executor.py", line 117, in migrate
initializer_1 | state = self._migrate_all_forwards(state, plan, full_plan, fake=fake, fake_initial=fake_initial)
initializer_1 | File "/usr/local/lib/python3.8/site-packages/django/db/migrations/executor.py", line 147, in _migrate_all_forwards
initializer_1 | state = self.apply_migration(state, migration, fake=fake, fake_initial=fake_initial)
initializer_1 | File "/usr/local/lib/python3.8/site-packages/django/db/migrations/executor.py", line 227, in apply_migration
initializer_1 | state = migration.apply(state, schema_editor)
initializer_1 | File "/usr/local/lib/python3.8/site-packages/django/db/migrations/migration.py", line 124, in apply
initializer_1 | operation.database_forwards(self.app_label, schema_editor, old_state, project_state)
initializer_1 | File "/usr/local/lib/python3.8/site-packages/django/db/migrations/operations/fields.py", line 104, in database_forwards
initializer_1 | schema_editor.add_field(
initializer_1 | File "/usr/local/lib/python3.8/site-packages/django/db/backends/mysql/schema.py", line 89, in add_field
initializer_1 | super().add_field(model, field)
initializer_1 | File "/usr/local/lib/python3.8/site-packages/django/db/backends/base/schema.py", line 487, in add_field
initializer_1 | self.execute(sql, params)
initializer_1 | File "/usr/local/lib/python3.8/site-packages/django/db/backends/base/schema.py", line 142, in execute
initializer_1 | cursor.execute(sql, params)
initializer_1 | File "/usr/local/lib/python3.8/site-packages/django/db/backends/utils.py", line 66, in execute
initializer_1 | return self._execute_with_wrappers(sql, params, many=False, executor=self._execute)
initializer_1 | File "/usr/local/lib/python3.8/site-packages/django/db/backends/utils.py", line 75, in _execute_with_wrappers
initializer_1 | return executor(sql, params, many, context)
initializer_1 | File "/usr/local/lib/python3.8/site-packages/django/db/backends/utils.py", line 84, in _execute
initializer_1 | return self.cursor.execute(sql, params)
initializer_1 | File "/usr/local/lib/python3.8/site-packages/django/db/utils.py", line 90, in exit
initializer_1 | raise dj_exc_value.with_traceback(traceback) from exc_value
initializer_1 | File "/usr/local/lib/python3.8/site-packages/django/db/backends/utils.py", line 84, in _execute
initializer_1 | return self.cursor.execute(sql, params)
initializer_1 | File "/usr/local/lib/python3.8/site-packages/django/db/backends/mysql/base.py", line 73, in execute
initializer_1 | return self.cursor.execute(query, args)
initializer_1 | File "/usr/local/lib/python3.8/site-packages/MySQLdb/cursors.py", line 206, in execute
initializer_1 | res = self._query(query)
initializer_1 | File "/usr/local/lib/python3.8/site-packages/MySQLdb/cursors.py", line 319, in _query
initializer_1 | db.query(q)
initializer_1 | File "/usr/local/lib/python3.8/site-packages/MySQLdb/connections.py", line 259, in query
initializer_1 | _mysql.connection.query(self, query)
initializer_1 | django.db.utils.OperationalError: (1060, "Duplicate column name 'sonarqube_config_id'")
initializer_1 | Applying dojo.0120_sonarqube_test_and_clean...Admin user: admin
initializer_1 | [01/Sep/2021 08:55:36] INFO [dojo.models:3627] disabling audit logging
initializer_1 | Admin password: Initialization detected that the admin user admin already exists in your database.

[valentijnscholten]

There were some changes #4931 that seem to now require false_p and duplicate fields to be present in the request. I didn't really understand that PR and I think we need to look at it again because too many fields seem to be mandatory while they have perfectly fine defaults.

@Maffooch @XiChen-Tibco IIRC you worked together on that PR?

The weird thing is that if we leave out false_p or duplicate you just get a 400 error, no error message or details. I had to do a binary search on all fields to find out these two are the culprit.

[Maffooch]

#4931 only seems to make active and verified required?

[valentijnscholten]

yeah, judged too soon. the missing error / trace seems to be because of #4863. If I remove that custom exception handler, the error is displayed (KeyError on duplicate field).

[valentijnscholten]

Looking at it some more it seems duplicate has always been mandatory, at least also in 2.1.0, so nothing changed in 2.2.0 except that the error message is getting hidden which is not what we want probably.

[valentijnscholten]

hmmm duplicate and false_p are not marked as required:

                "required": [
                    "active",
                    "created",
                    "description",
                    "duplicate_finding",
                    "files",
                    "found_by",
                    "hash_code",
                    "id",
                    "last_reviewed",
                    "last_reviewed_by",
                    "last_status_update",
                    "line_number",
                    "mitigated",
                    "mitigated_by",
                    "notes",
                    "numerical_severity",
                    "param",
                    "payload",
                    "reporter",
                    "scanner_confidence",
                    "severity",
                    "sourcefile",
                    "sourcefilepath",
                    "test",
                    "title",
                    "verified"
                ]

I thought the purpose of #4931 was to have the full list of required fields in the openapi spec.

[valentijnscholten]

I have reopened the original bug report on fields not being marked as required. This bug report here is now renamed to cover the bug that exceptions are swallowed.

[QuentinVsm]

Works perfect for me. Thank for being that reactive !

[StefanFl]

Error messages shouldn't reveal internal information as a security practice:

https://cheatsheetseries.owasp.org/cheatsheets/Error_Handling_Cheat_Sheet.html:

The outcome being that when an unexpected error occurs then a generic response is returned by the application but the error details are logged server side for investigation, and not returned to the user.

The application should try and exhaustively cover all possible failure modes and use 5xx errors only to indicate responses to requests that it cannot fulfill, but not provide any content as part of the response that would reveal implementation details.

That is exactly what DefectDojo is doing now and I would consider it as a feature rather than a bug.

[valentijnscholten]

The problem is the error is not in the logs anymore. Also with DEBUG off, Django usually doesn't return the full details anyway.

[damiencarol]

I guess we could work to have this errors in logs again and a more generic error, like "duplicate attribute is missing" (which is aligned with OWASP description).

[StefanFl]

@valentijnscholten Do you like to see a change of the exception handler or is your fix with the logging sufficient?

[valentijnscholten]

We have had a couple of occasions where the error handlings was (unknowingly) changed into something that hid the error details from the response (even in DEBUG mode) or swallowed errors (not logging them). So ideally we have some test cases where we capture the current error handling behaviour so we will notice it when something changes. We can also check if everybody is happy with the current error handling. I know it's best practice to hide errors, but we also need to allow users to easily debug their problems (so we don't have to be on slack 24/7 :-))

[stale]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.