Improve error reporting when an operation fails

[susanodd]

Instead of just try-except pass around error messages to report back. Also for transactions that fail. Also for file system errors.
This is non-trivial.

Kindly report use cases (including API) where something is going wrong but this isn't reported sufficiently.

[susanodd]

@rem0g are you busy trying to upload a zip file?

In the error log it was giving errors about the api token.

[rem0g]

Yes, sometimes video_upload returns whole django HTML template so my script doesnt know how to interprent that. It will keep for looping that same video file, so error reporting should be always in JSON format.

Sometimes i'm getting Failed to upload message, though there is no reason attached as why it happens.

I will continue to run the script as some videos are uploaded succesfully, but I am not satisfied with how Signbank handles the video upload process so we will need another method to handle the videos as in the future we will have to process thousands of videos every week (happening now).

I am getting fails with gloss with special chars for example:
"DISNEY+-A"
"#WDD"

Also Signbank notifies the video is not h264 but yet the video is there on Signbank.

@Woseseltops i think the video upload process needs a do-over;
A seperate python file to retrieve video file via POST and process as is, it's not needed to check whether it's h264. If it doesnt play, it wont play and we will know that one way or another.
JSON file so i can check every moment if the upload and placing the video has been successful.

[Jetske]

@rem0g what is a good way to report errors? Returning a JsonResponse with the error? I'm trying to add checks into the APIs for example sentences.

[Woseseltops]

Indeed @Jetske , something like this:

return JsonResponse({'error': 'Invalid request'}, status=400)

In addition to that, using the correct error code would be even better:

• 400 Bad Request: The request was malformed.
• 401 Unauthorized: Authentication is needed.
• 402 Payment Required: Reserved for future use.
• 403 Forbidden: The server understood the request but refuses to authorize it.
• 404 Not Found: The requested resource could not be found.
• 405 Method Not Allowed: The request method is not supported for the resource.

@rem0g , I'll create a separate issue for your video upload suggestions!

[susanodd]

The error reporting I added for gloss updates (Batch Edit and API) reports type errors, for example choices that don't exist.

[susanodd]

@rem0g have you been able to use the NME API functions all right?

[susanodd]

Indeed @Jetske , something like this:

return JsonResponse({'error': 'Invalid request'}, status=400)

In addition to that, using the correct error code would be even better:

• 400 Bad Request: The request was malformed.
• 401 Unauthorized: Authentication is needed.
• 402 Payment Required: Reserved for future use.
• 403 Forbidden: The server understood the request but refuses to authorize it.
• 404 Not Found: The requested resource could not be found.
• 405 Method Not Allowed: The request method is not supported for the resource.

@rem0g , I'll create a separate issue for your video upload suggestions!

Is there anything for "type checking"? Or do we make a new status code for this?
I guess it could fall under "Bad Request" but that is totally not helpful at all.
The POST arguments are wrong (possible error result)
Also we have Constraint Violation (possible error result)

[susanodd]

@rem0g do you know what specific API you called that reported that it failed but it did not? It's probably something with variable scoping in the various branches.

And you don't want the check whether it's h264.
If I remove that it should help with the error reporting. [REMOVED]

I think there was a conflict between using a json field "status" versus e.g., "updatestatus".
I came across that in javascript. The "status" is already used by javascript/ajax. (It's a keyword, like "data".)
The zip upload uses "status". Maybe that is causing problems? [CHANGED]

Is it possible that the one that reported an error but still seemed to have worked was "replacing" a video?
I found a place in the code where it is checked that a video path exists rather than checking the errors field.
(It would be possible that the video file was not replaced.) [THAT'S A GUESS]

[susanodd]

@rem0g I can see that there are Disney video files:

(env) root@signbank-new:/var/www/repo# ls -l ../writable/glossvideo/NGT/DI/DISNEY*
-rw-r--r-- 1 ubuntu www-data 1319804 Mar 25  2024 ../writable/glossvideo/NGT/DI/DISNEY-A-47512.bak.bak
-rw-r--r-- 1 ubuntu www-data 1899244 Sep 23 10:09 ../writable/glossvideo/NGT/DI/DISNEY-A-47512.mp4
-rw-r--r-- 1 ubuntu www-data 1805995 Sep 23 10:09 ../writable/glossvideo/NGT/DI/DISNEY-B-47513.mp4
-rw-r--r-- 1 ubuntu www-data 2260995 Sep 19 07:02 ../writable/glossvideo/NGT/DI/DISNEY-C-48427.mp4
-rw-r--r-- 1 ubuntu www-data 2442557 Sep 19 07:02 ../writable/glossvideo/NGT/DI/DISNEY-D-48428.mp4
(env) root@signbank-new:/var/www/repo# 

Of the above, DISNEY-C and DISNEY-D do not show on signbank, in spite of the video files existing.

https://signbank.cls.ru.nl/dictionary/gloss/48427

https://signbank.cls.ru.nl/dictionary/gloss/48428

@Woseseltops @vanlummelhuizen any idea what's going on here?

[UPDATE] With numerous repeated zip imports I was able to get the second code branch to be taken. It's when there is no video yet. The path is wrong there. The branch is only when there is no video object at all. I had to remove objects and files to get that branch to be taken. I suspect seeing that so many import operations were done that the rest are failing for other reasons, but because of an initial wrong path. The video code does not actually delete files because of a setting in default. But it has try-except calls that seem to just ignore.

[susanodd]

In the video history I can see you uploaded the DISNEY videos numerous times. (74 times)

Below, you can see the path stored in the object is wrong. (Need to figure out where it is setting this wrong in the code. it's stored as a relative path, but it's displayed here as a full path. the relative path is wrong but the video is stored correctly on the file system.)

[susanodd]

The above error is high priority!!!

The code does not know it's doing anything wrong.
In the log, there are no error messages when importing videos.

I can see that the "create still image" is using a file in the wrong location:

Video file: /home/susan/signbank/writable/SLIM-D-48844.mp4

It's missing the "glossvideo/NGT/SL" from the path.

But I can't see where it is getting this from, nor where the method is being called. (There are numerous imports from different python files.)

The code is unaware that it is doing anything wrong / does not report errors, because of try-except on OS calls, so it basically does "pass" on some low-level things outside of Django.
I fixed some to report back.

But hypothetically, what would be the behaviour if the file system/database is not wanting to save? Just crash an operation that is supposed to import hundreds of videos? (Is importing a bunch of videos "one" operation?)
There are a potential avalanche of errors. Esp. if operations are done 74 times

[susanodd]

Up to here, the repairs commented about above:

• to video import (fixed path problem with gloss video object, do not check h264, do not return video link if import went wrong)
• report the dataset a gloss is in if not selected

have been deployed.

Regarding the first one, if you go to the Dataset Media Manager (via the Manage Datasets page) you will see for NGT that the videos previously shown as "not mp4" can now be imported (the probe is not applied to the files anymore).

I removed the video files and their gloss video objects that were in "writable" instead of in "writable/NGT/XX"
Otherwise you would not be able to import them successfully again. (Django does not allow to delete GlossVideo objects unless the video file is gone.)

[Woseseltops]

Is there anything for "type checking"? Or do we make a new status code for this? I guess it could fall under "Bad Request" but that is totally not helpful at all.

I would say:

return JsonResponse({'error': 'Explanation of what went wrong type checking.'}, status=400)

[susanodd]

About the csrf token exception, I have no idea. The code worked fine before the API token and processing was introduced. It also worked on the signbank-dev server at that time. I can only assume other changes for using the API token messed it up somehow. We never put the csrf except on anything before. You only needed to be logged in. Maybe the swagger is doing something different because it's not actually Signbank.

Swagger isn't logged in, it's only using the API token.

[susanodd]

OK, uploading a zip and then importing it works, but only after I had to solve some problems.

First, the next two lines delete uploaded videos from a zip before they can be imported. So, the lines should be deleted:

Global-signbank/signbank/zip_interface.py

Lines 138 to 139 in 8c555a0

	if os.path.exists(unzipped_folder):
	shutil.rmtree(unzipped_folder)

Then, there needs to be a slash ("/") after the endpoint `"/dictionary/upload_videos_to_glosses/{datasetid}":

Global-signbank/docs/signbank-api.json

Line 859 in 8c555a0

"/dictionary/upload_videos_to_glosses/{datasetid}":

Finally, upload_videos_to_glosses (see below) needs a csrf_exempt decorator.

Global-signbank/signbank/api_interface.py

Lines 453 to 455 in 8c555a0

	@put_api_user_in_request
	def upload_videos_to_glosses(request, datasetid):

Questions:

1. Why two endpoints for one process, that of uploading a zip with videos?

2. Why should the file be downloadable from elsewhere and not via POST request, similar to uploading files on a web page?

3. Why upload a precisely prepared zip when you can upload videos directly with info for dataset, language and/or gloss in the POST request? Since it is an API it is up to the client to handle multiple video uploads.

The uploaded (unzipped) videos are first put in another location, in the import folder.
That's why the tree is removed there.

[susanodd]

@vanlummelhuizen I made the changes for the ZIP code you showed above.
I have the code on signbank-test.

It took a while to figure out what was wrong.
It turns out I had a folder FIRST as a dataset folder under glossvideo.
That was from when i was trying to make a signbank with an empty dataset.

The the dataset folders NEED to be already created in glossvideo.
Otherwise importing the zipped files does not work at all.
Apparently it does not bother to create a dataset folder. (We assume this already exists.)
(The tests also do not check this.)
So once I created the dataset folders, it works now to import a zip file in the Media Manager.

[susanodd]

Up to here, the fixes shown above have all been deployed on signbank.

[susanodd]

I found this in the logs:

response = get_response(request)
           ^^^^^^^^^^^^^^^^^^^^^

File "/var/www/env/lib/python3.12/site-packages/django/core/handlers/base.py", line 197, in _get_response
response = wrapped_callback(request, *callback_args, **callback_kwargs)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/var/www/repo/signbank/dictionary/views.py", line 2334, in protected_media
gloss_pk = int(filename.split('.')[-2].split('-')[-1])
~~~~~~~~~~~~~~~~~~~^^^^
IndexError: list index out of range
Internal Server Error: /dictionary/protected_media/glossvideo/NGT/AA/%c0%ae%c0%ae%c0%af%c0%ae%c0%ae%c0%af%c0%ae%c0%ae%c0%af%c0%ae%c0%ae%c0
%af%c0%ae%c0%ae%c0%af%c0%ae%c0%ae%c0%af%c0%ae%c0%ae%c0%af%c0%ae%c0%ae%c0%afetc/passwd
Traceback (most recent call last):
File "/var/www/env/lib/python3.12/site-packages/django/core/handlers/exception.py", line 55, in inner
response = get_response(request)
^^^^^^^^^^^^^^^^^^^^^
File "/var/www/env/lib/python3.12/site-packages/django/core/handlers/base.py", line 197, in _get_response
response = wrapped_callback(request, *callback_args, **callback_kwargs)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/var/www/repo/signbank/dictionary/views.py", line 2334, in protected_media
gloss_pk = int(filename.split('.')[-2].split('-')[-1])
~~~~~~~~~~~~~~~~~~~^^^^
IndexError: list index out of range

[susanodd]

Internal Server Error: /dictionary/protected_media/handshapeimage/62/
Traceback (most recent call last):
  File "/var/www/env/lib/python3.12/site-packages/django/core/handlers/exception.py", line 55, in inner
    response = get_response(request)
               ^^^^^^^^^^^^^^^^^^^^^
  File "/var/www/env/lib/python3.12/site-packages/django/core/handlers/base.py", line 197, in _get_response
    response = wrapped_callback(request, *callback_args, **callback_kwargs)
               ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/var/www/repo/signbank/dictionary/views.py", line 2334, in protected_media
    gloss_pk = int(filename.split('.')[-2].split('-')[-1])
                   ~~~~~~~~~~~~~~~~~~~^^^^
IndexError: list index out of range

[susanodd]

[pid: 331|app: 0|req: 71191/368626] 10.208.155.251 () {60 vars in 2445 bytes} [Mon Oct  7 04:51:04 2024] GET /dictionary/protected_media/h
andshapeimage/62/%25c0%25ae%25c0%25ae%25c0%25af%25c0%25ae%25c0%25ae%25c0%25af%25c0%25ae%25c0%25ae%25c0%25af%25c0%25ae%25c0%25ae%25c0%25af%
25c0%25ae%25c0%25ae%25c0%25af%25c0%25ae%25c0%25ae%25c0%25af%25c0%25ae%25c0%25ae%25c0%25af%25c0%25ae%25c0%25ae%25c0%25af%25c0%25ae%25c0%25a
e%25c0%25af%25c0%25ae%25c0%25ae%25c0%25af%25c0%25ae%25c0%25ae%25c0%25af%25c0%25ae%25c0%25ae%25c0%25af%25c0%25ae%25c0%25ae%25c0%25af%25c0%2
5ae%25c0%25ae%25c0%25af%25c0%25ae%25c0%25ae%25c0%25af%25c0%25ae%25c0%25ae%25c0%25af/etc/passwd => generated 90131 bytes in 209 msecs (HTTP
/1.1 500) 5 headers in 185 bytes (1 switches on core 1)

Why is there an "/etc/passwd" stuck on the end of the url?
Is this the same hackers that created the fake user accounts?

It's even worse here:

[pid: 330|app: 0|req: 40763/368645] 10.208.155.251 () {60 vars in 1503 bytes} [Mon Oct  7 04:51:05 2024] GET /dictionary/protected_media/h
andshapeimage/7/..../..../..../..../..../..../..../..../etc/passwd => generated 85627 bytes in 29 msecs (HTTP/1.1 500) 5 headers in 185 by
tes (1 switches on core 3)
Internal Server Error: /dictionary/protected_media/glossvideo/NGT/AA/..%C1%9C..%C1%9C..%C1%9C..%C1%9C..%C1%9C..%C1%9C..%C1%9C..%C1%9C/wind
ows/win.ini
Traceback (most recent call last):
  File "/var/www/env/lib/python3.12/site-packages/django/core/handlers/exception.py", line 55, in inner
    response = get_response(request)

[susanodd]

How to fix this, or is there nothing to do about these malicious urls?

[susanodd]

So if a user tries to enter a bogus URL to a video or image, then try except the only line of code above and do a "Forbidden" ?

What are they trying to do? Get the server to switch to a console or something?

[susanodd]

Forbidden (CSRF token from POST has incorrect length.): /dictionary/handshape/173/
Internal Server Error: /dictionary/protected_media/glossvideo/NGT/TW/%C0%AE%C0%AE/WEB-INF/web.xml

[susanodd]

Here's more recent, I decided to skip those 200000 lines of hackers.

[pid: 848|app: 0|req: 14335/31659] 10.208.155.251 () {62 vars in 1124 bytes} [Thu Oct 10 14:40:07 2024] POST /dictionary/api_update_gloss/
5/47041/ => generated 61 bytes in 79 msecs (HTTP/1.1 200) 5 headers in 147 bytes (1 switches on core 1)
[pid: 848|app: 0|req: 14336/31660] 10.208.155.251 () {62 vars in 1124 bytes} [Thu Oct 10 14:40:07 2024] POST /dictionary/api_update_gloss/
5/47050/ => generated 61 bytes in 88 msecs (HTTP/1.1 200) 5 headers in 147 bytes (1 switches on core 2)
[pid: 844|app: 0|req: 8701/31661] 10.208.155.251 () {62 vars in 1124 bytes} [Thu Oct 10 14:40:07 2024] POST /dictionary/api_update_gloss/5
/47050/ => generated 61 bytes in 95 msecs (HTTP/1.1 200) 5 headers in 147 bytes (1 switches on core 0)
[pid: 844|app: 0|req: 8702/31662] 10.208.155.251 () {62 vars in 1124 bytes} [Thu Oct 10 14:40:07 2024] POST /dictionary/api_update_gloss/5
/47051/ => generated 61 bytes in 86 msecs (HTTP/1.1 200) 5 headers in 147 bytes (1 switches on core 1)
[pid: 844|app: 0|req: 8703/31663] 10.208.155.251 () {62 vars in 1124 bytes} [Thu Oct 10 14:40:08 2024] POST /dictionary/api_update_gloss/5
/47053/ => generated 61 bytes in 82 msecs (HTTP/1.1 200) 5 headers in 147 bytes (1 switches on core 3)
Internal Server Error: /dictionary/api_update_gloss/5/48628/
Traceback (most recent call last):
  File "/var/www/env/lib/python3.12/site-packages/django/db/backends/utils.py", line 89, in _execute
    return self.cursor.execute(sql, params)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/var/www/env/lib/python3.12/site-packages/django/db/backends/sqlite3/base.py", line 328, in execute
    return super().execute(query, params)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
sqlite3.OperationalError: database is locked

So after a number of successful API gloss updates, the database is locked.

The database locked is after a gloss.save()

@Woseseltops what to do about this?

  File "/var/www/repo/signbank/gloss_update.py", line 626, in api_update_gloss
    gloss_update_do_changes(request.user, gloss, fields_to_update, interface_language_code)
  File "/var/www/repo/signbank/gloss_update.py", line 483, in gloss_update_do_changes
    gloss.save()

[susanodd]

Here it is in context:

[pid: 840|app: 0|req: 5405/31682] 10.208.155.251 () {60 vars in 1255 bytes} [Thu Oct 10 14:39:27 2024] GET /dictionary/package/?extended_f
ields=true&since_timestamp=1728563701 => generated 863033 bytes in 44584 msecs (HTTP/1.1 200) 6 headers in 242 bytes (1 switches on core 3
)
[pid: 840|app: 0|req: 5406/31683] 10.208.155.251 () {62 vars in 1124 bytes} [Thu Oct 10 14:40:12 2024] POST /dictionary/api_update_gloss/5
/47079/ => generated 61 bytes in 92 msecs (HTTP/1.1 200) 5 headers in 147 bytes (1 switches on core 0)
[pid: 848|app: 0|req: 14343/31684] 10.208.155.251 () {62 vars in 1124 bytes} [Thu Oct 10 14:40:12 2024] POST /dictionary/api_update_gloss/
5/47079/ => generated 61 bytes in 76 msecs (HTTP/1.1 200) 5 headers in 147 bytes (1 switches on core 2)
[pid: 844|app: 0|req: 8710/31685] 10.208.155.251 () {62 vars in 1124 bytes} [Thu Oct 10 14:40:12 2024] POST /dictionary/api_update_gloss/5
/49321/ => generated 61 bytes in 69 msecs (HTTP/1.1 200) 5 headers in 147 bytes (1 switches on core 3)
[pid: 840|app: 0|req: 5407/31686] 10.208.155.251 () {62 vars in 1124 bytes} [Thu Oct 10 14:40:12 2024] POST /dictionary/api_update_gloss/5
/47072/ => generated 61 bytes in 116 msecs (HTTP/1.1 200) 5 headers in 147 bytes (1 switches on core 1)
[pid: 839|app: 0|req: 3227/31687] 10.208.155.251 () {62 vars in 1124 bytes} [Thu Oct 10 14:40:13 2024] POST /dictionary/api_update_gloss/5
/44296/ => generated 61 bytes in 108 msecs (HTTP/1.1 200) 5 headers in 147 bytes (1 switches on core 1)
[pid: 848|app: 0|req: 14344/31688] 10.208.155.251 () {62 vars in 1124 bytes} [Thu Oct 10 14:40:13 2024] POST /dictionary/api_update_gloss/
5/47527/ => generated 61 bytes in 89 msecs (HTTP/1.1 200) 5 headers in 147 bytes (1 switches on core 0)
[pid: 848|app: 0|req: 14345/31689] 10.208.155.251 () {62 vars in 1124 bytes} [Thu Oct 10 14:40:13 2024] POST /dictionary/api_update_gloss/
5/46299/ => generated 61 bytes in 76 msecs (HTTP/1.1 200) 5 headers in 147 bytes (1 switches on core 3)
[pid: 848|app: 0|req: 14346/31690] 10.208.155.251 () {62 vars in 1124 bytes} [Thu Oct 10 14:40:13 2024] POST /dictionary/api_update_gloss/
5/46299/ => generated 61 bytes in 74 msecs (HTTP/1.1 200) 5 headers in 147 bytes (1 switches on core 1)
Internal Server Error: /dictionary/api_update_gloss/5/47694/
Traceback (most recent call last):
  File "/var/www/env/lib/python3.12/site-packages/django/db/backends/utils.py", line 89, in _execute
    return self.cursor.execute(sql, params)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/var/www/env/lib/python3.12/site-packages/django/db/backends/sqlite3/base.py", line 328, in execute
    return super().execute(query, params)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
sqlite3.OperationalError: database is locked

A package is done, then 8 update gloss calls, then the database is locked.

@Woseseltops @vanlummelhuizen look here.

(There are no other operations between the API calls. The database getting locked is not caused by other users, but by the API calls.)

[susanodd]

Question: Can we force the API calls to fail if the database is locked? Otherwise the stuff afterwards just keeps causing errors. Django ought to refuse new API requests.

[susanodd]

@vanlummelhuizen what is the best kind of response to "revoke" all of those "hacker" type url requests? #1331 (comment)
They ought to be revoked before the server tries to process them. Are there Django settings? It's a bunch of bogus stuff stuck on at the end of legitimate urls.

I got rid of the search parameters by using the query parameters. But that is not all-encompassing.
We need some intermediate routine to clean up the GET parameters and reject requests at the access level on abuse.
Is there a request method annotation to be strict and not allow bogus stuff at the end?

[susanodd]

I removed the bogus user accounts that showed up in the database last week.
It was pieces of code used as user names.
The most recent database copy on my tensusers you can see those bogus user accounts in that.
Maybe the most recent Django robot pull request upgrade fixes that.

[susanodd]

sqlite3.connect has an optional isolation_level parameter, which controls the database locking behavior during transactions.

In DEFERRED (the default) mode, a transaction acquires a read lock on the database when it begins, and a write lock only when a write operation is requested.
In IMMEDIATE mode, a transaction acquires a write lock immediately, even if it's only performing read operations. Other transactions attempting to write to the database will be blocked, but read-only transactions can still proceed.
In EXCLUSIVE mode, a transaction acquires an exclusive lock on the database, blocking all other transactions, reading or writing, until the current transaction is committed or rolled back.

[susanodd]

From Django's documentation:

SQLite is meant to be a lightweight database, and thus can't support a high level of concurrency. OperationalError: database is locked errors indicate that your application is experiencing more concurrency than sqlite can handle in default configuration. This error means that one thread or process has an exclusive lock on the database connection and another thread timed out waiting for the lock the be released.

[vanlummelhuizen]

About moving away from SQLite: #673

About request from hackers: Django seems to handle those correctly, responding with error 500. If you want to know more about security (hardening) search for 'django security hardening'. One thing I came across that might be of use: https://djcheckup.com/.

About bogus user registrations: we propably needs to review registrations once in a while. But I think it should be an Amsterdam task. Perhaps we could make a cronjob that make a daily email with al new registration and send that to Ulrika for instance.

[susanodd]

Here is where the database is with the bogus users still in it (tensusers): signbank_101024.db

[susanodd]

@vanlummelhuizen do I need to add a try-except on all the save methods? And throw an error to the API if the database is locked?

I don't know if methods that fail clean up after themselves.