Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Key constraint issues, retry / lookup queries forfailed job #4033

Open
underdarknl opened this issue Jan 17, 2025 · 2 comments
Open

Key constraint issues, retry / lookup queries forfailed job #4033

underdarknl opened this issue Jan 17, 2025 · 2 comments
Labels
boefjes Issues related to boefjes bug Something isn't working

Comments

@underdarknl
Copy link
Contributor

Please add bug, the name of any relevant modules (e.g. rocky), and any other relevant labels to your issue.

Describe the bug

I'm seeing the following logs on postgres:

5-01-17 08:21:11.895 UTC [8025] ERROR:  duplicate key value violates unique constraint "boefje_meta_pkey"
2025-01-17 08:21:11.895 UTC [8025] DETAIL:  Key (id)=(1ad000dd-edd8-4f8a-ae42-70563ea1ad4a) already exists.
2025-01-17 08:21:11.895 UTC [8025] STATEMENT:  INSERT INTO boefje_meta (id, boefje_id, boefje_version, organization, input_ooi, arguments, environment, runnable_hash, started_at, ended_at) VALUES ('1ad000dd-edd8-4f8a-ae42-70563ea1ad4a'::uuid, 'security_txt_downloader', NULL, 'test', 'Website|internet|185.73.32.3|tcp|80|http|internet|css.underdark.nl', '{"input": {"object_type": "Website", "scan_profile": "scan_profile_type=''inherited'' reference=Reference(''Website|internet|185.73.32.3|tcp|80|http|internet|css.underdark.nl'') level=<ScanLevel.L2: 2> user_id=None", "user_id": "None", "primary_key": "Website|internet|185.73.32.3|tcp|80|http|internet|css.underdark.nl", "ip_service": {"ip_port": {"address": {"network": {"name": "internet"}, "address": "185.73.32.3"}, "protocol": "tcp", "port": "80"}, "service": {"name": "http"}}, "hostname": {"network": {"name": "internet"}, "name": "css.underdark.nl"}, "certificate": "None"}}', '{}', '3457f1ec8b651fb4fa6caeedeb70b367cf6d1a6728075648668251d1894cefb1', '2025-01-17T08:21:10.926257+00:00'::timestamptz, '2025-01-17T08:21:11.891491+00:00'::timestamptz)

This is followed up by a read from Octopoes for that specific OOI every few seconds.


172.30.0.14:42738 - "GET /test/object?reference=Hostname%7Cinternet%7Ccss.underdark.nl&valid_time=2025-01-17%2010%3A50%3A35.605765%2B00%3A00 HTTP/1.1" 200
172.30.0.14:53806 - "GET /test/object?reference=Hostname%7Cinternet%7Ccss.underdark.nl&valid_time=2025-01-17%2010%3A51%3A35.653344%2B00%3A00 HTTP/1.1" 200
172.30.0.14:36802 - "GET /test/object?reference=Hostname%7Cinternet%7Ccss.underdark.nl&valid_time=2025-01-17%2010%3A52%3A35.709503%2B00%3A00 HTTP/1.1" 200
172.30.0.14:52048 - "GET /test/object?reference=Hostname%7Cinternet%7Ccss.underdark.nl&valid_time=2025-01-17%2010%3A53%3A35.811916%2B00%3A00 HTTP/1.1" 200
172.30.0.14:58242 - "GET /test/object?reference=Hostname%7Cinternet%7Ccss.underdark.nl&valid_time=2025-01-17%2010%3A54%3A35.855342%2B00%3A00 HTTP/1.1" 200
172.30.0.14:56862 - "GET /test/object?reference=Hostname%7Cinternet%7Ccss.underdark.nl&valid_time=2025-01-17%2010%3A55%3A35.903854%2B00%3A00 HTTP/1.1" 200
172.30.0.14:45248 - "GET /test/object?reference=Hostname%7Cinternet%7Ccss.underdark.nl&valid_time=2025-01-17%2010%3A56%3A35.959063%2B00%3A00 HTTP/1.1" 200
172.30.0.14:37976 - "GET /test/object?reference=Hostname%7Cinternet%7Ccss.underdark.nl&valid_time=2025-01-17%2010%3A57%3A36.027924%2B00%3A00 HTTP/1.1" 200
172.30.0.14:33248 - "GET /test/object?reference=Hostname%7Cinternet%7Ccss.underdark.nl&valid_time=2025-01-17%2010%3A58%3A36.092760%2B00%3A00 HTTP/1.1" 200
172.30.0.14:39830 - "GET /test/object?reference=Hostname%7Cinternet%7Ccss.underdark.nl&valid_time=2025-01-17%2010%3A59%3A36.141722%2B00%3A00 HTTP/1.1" 200
172.30.0.14:59512 - "GET /test/object?reference=Hostname%7Cinternet%7Ccss.underdark.nl&valid_time=2025-01-17%2011%3A00%3A36.191452%2B00%3A00 HTTP/1.1" 200
172.30.0.14:36218 - "GET /test/object?reference=Hostname%7Cinternet%7Ccss.underdark.nl&valid_time=2025-01-17%2011%3A01%3A36.710511%2B00%3A00 HTTP/1.1" 200
172.30.0.14:56538 - "GET /test/object?reference=Hostname%7Cinternet%7Ccss.underdark.nl&valid_time=2025-01-17%2011%3A02%3A36.761285%2B00%3A00 HTTP/1.1" 200
172.30.0.14:45680 - "GET /test/object?reference=Hostname%7Cinternet%7Ccss.underdark.nl&valid_time=2025-01-17%2011%3A03%3A36.817759%2B00%3A00 HTTP/1.1" 200

And from bytes:


172.30.0.14:46836 - "GET /bytes/boefje_meta?boefje_id=dns-sec&input_ooi=Hostname%7Cinternet%7Ccss.underdark.nl&organization=test&limit=1&descending=true HTTP/1.1" 200
172.30.0.14:49110 - "GET /bytes/boefje_meta?boefje_id=dns-sec&input_ooi=Hostname%7Cinternet%7Ccss.underdark.nl&organization=test&limit=1&descending=true HTTP/1.1" 200
172.30.0.14:34074 - "GET /bytes/boefje_meta?boefje_id=dns-sec&input_ooi=Hostname%7Cinternet%7Ccss.underdark.nl&organization=test&limit=1&descending=true HTTP/1.1" 200
172.30.0.14:41868 - "GET /bytes/boefje_meta?boefje_id=dns-sec&input_ooi=Hostname%7Cinternet%7Ccss.underdark.nl&organization=test&limit=1&descending=true HTTP/1.1" 200
172.30.0.14:60720 - "GET /bytes/boefje_meta?boefje_id=dns-sec&input_ooi=Hostname%7Cinternet%7Ccss.underdark.nl&organization=test&limit=1&descending=true HTTP/1.1" 200
172.30.0.14:38156 - "GET /bytes/boefje_meta?boefje_id=dns-sec&input_ooi=Hostname%7Cinternet%7Ccss.underdark.nl&organization=test&limit=1&descending=true HTTP/1.1" 200
172.30.0.14:34246 - "GET /bytes/boefje_meta?boefje_id=dns-sec&input_ooi=Hostname%7Cinternet%7Ccss.underdark.nl&organization=test&limit=1&descending=true HTTP/1.1" 200
172.30.0.14:39414 - "GET /bytes/boefje_meta?boefje_id=dns-sec&input_ooi=Hostname%7Cinternet%7Ccss.underdark.nl&organization=test&limit=1&descending=true HTTP/1.1" 200
172.30.0.14:57574 - "GET /bytes/boefje_meta?boefje_id=dns-sec&input_ooi=Hostname%7Cinternet%7Ccss.underdark.nl&organization=test&limit=1&descending=true HTTP/1.1" 200
172.30.0.14:56414 - "GET /bytes/boefje_meta?boefje_id=dns-sec&input_ooi=Hostname%7Cinternet%7Ccss.underdark.nl&organization=test&limit=1&descending=true HTTP/1.1" 200

The boefje log indicated an initial upload to Bytes for the raw file was sucesfull, but it tried again and then failed. It then also failed to path the status to "failed".

Grepped for the UUID:

2025-01-17T08:21:07.726103 [info] Handling task[1ad000dd-edd8-4f8a-ae42-70563ea1ad4a]
2025-01-17T08:21:07.726768 [info] Dispatched task[1ad000dd-edd8-4f8a-ae42-70563ea1ad4a]
2025-01-17T08:21:07.771089 [info] Handling task[1ad000dd-edd8-4f8a-ae42-70563ea1ad4a]
2025-01-17T08:21:07.771816 [info] Dispatched task[1ad000dd-edd8-4f8a-ae42-70563ea1ad4a]
HTTP Request: PATCH http://scheduler:8000/tasks/1ad000dd-edd8-4f8a-ae42-70563ea1ad4a "HTTP/1.1 200 OK"
2025-01-17T08:21:08.833398 [info] Handling boefje security_txt_downloader[task_id=1ad000dd-edd8-4f8a-ae42-70563ea1ad4a]
2025-01-17T08:21:08.927601 [info] Starting boefje security_txt_downloader[1ad000dd-edd8-4f8a-ae42-70563ea1ad4a]
2025-01-17T08:21:08.945782 [error] Error running boefje security_txt_downloader[1ad000dd-edd8-4f8a-ae42-70563ea1ad4a]
│ │                         │   id=UUID('1ad000dd-edd8-4f8a-ae42-70563ea1ad4a'),                 │ │
│ │               │   id=UUID('1ad000dd-edd8-4f8a-ae42-70563ea1ad4a'),                           │ │
│ │                  │   id=UUID('1ad000dd-edd8-4f8a-ae42-70563ea1ad4a'),                        │ │
│ │                         │   id=UUID('1ad000dd-edd8-4f8a-ae42-70563ea1ad4a'),                 │ │
2025-01-17T08:21:09.798073 [info] Saving to Bytes for boefje security_txt_downloader[1ad000dd-edd8-4f8a-ae42-70563ea1ad4a]
HTTP Request: POST http://bytes:8000/bytes/raw?boefje_meta_id=1ad000dd-edd8-4f8a-ae42-70563ea1ad4a "HTTP/1.1 200 OK"
2025-01-17T08:21:09.858527 [info] Saved raw file 5535b23d-ca74-4b2f-970f-0dde1d8f79d9 for boefje security_txt_downloader[1ad000dd-edd8-4f8a-ae42-70563ea1ad4a]
2025-01-17T08:21:09.858666 [error] An error occurred handling scheduler item[id=1ad000dd-edd8-4f8a-ae42-70563ea1ad4a]
│ │                         │   id=UUID('1ad000dd-edd8-4f8a-ae42-70563ea1ad4a'),                 │ │
│ │               │   id=UUID('1ad000dd-edd8-4f8a-ae42-70563ea1ad4a'),                           │ │
│ │                    │   id=UUID('1ad000dd-edd8-4f8a-ae42-70563ea1ad4a'),                      │ │
│ │                    │   │   id=UUID('1ad000dd-edd8-4f8a-ae42-70563ea1ad4a'),                  │ │
│ │                           │   id=UUID('1ad000dd-edd8-4f8a-ae42-70563ea1ad4a'),               │ │
│ │                         │   id=UUID('1ad000dd-edd8-4f8a-ae42-70563ea1ad4a'),                 │ │
HTTP Request: GET http://scheduler:8000/tasks/1ad000dd-edd8-4f8a-ae42-70563ea1ad4a "HTTP/1.1 200 OK"
HTTP Request: PATCH http://scheduler:8000/tasks/1ad000dd-edd8-4f8a-ae42-70563ea1ad4a "HTTP/1.1 200 OK"
2025-01-17T08:21:10.802787 [info] Set status to TaskStatus.FAILED in the scheduler for task[id=1ad000dd-edd8-4f8a-ae42-70563ea1ad4a]
HTTP Request: PATCH http://scheduler:8000/tasks/1ad000dd-edd8-4f8a-ae42-70563ea1ad4a "HTTP/1.1 200 OK"
2025-01-17T08:21:10.811284 [info] Handling boefje security_txt_downloader[task_id=1ad000dd-edd8-4f8a-ae42-70563ea1ad4a]
2025-01-17T08:21:10.926151 [info] Starting boefje security_txt_downloader[1ad000dd-edd8-4f8a-ae42-70563ea1ad4a]
2025-01-17T08:21:10.946494 [error] Error running boefje security_txt_downloader[1ad000dd-edd8-4f8a-ae42-70563ea1ad4a]
│ │                         │   id=UUID('1ad000dd-edd8-4f8a-ae42-70563ea1ad4a'),                 │ │
│ │               │   id=UUID('1ad000dd-edd8-4f8a-ae42-70563ea1ad4a'),                           │ │
│ │                  │   id=UUID('1ad000dd-edd8-4f8a-ae42-70563ea1ad4a'),                        │ │
│ │                         │   id=UUID('1ad000dd-edd8-4f8a-ae42-70563ea1ad4a'),                 │ │
2025-01-17T08:21:11.891566 [info] Saving to Bytes for boefje security_txt_downloader[1ad000dd-edd8-4f8a-ae42-70563ea1ad4a]
2025-01-17T08:21:11.911553 [error] An error occurred handling scheduler item[id=1ad000dd-edd8-4f8a-ae42-70563ea1ad4a]
│ │                         │   id=UUID('1ad000dd-edd8-4f8a-ae42-70563ea1ad4a'),                 │ │
│ │               │   id=UUID('1ad000dd-edd8-4f8a-ae42-70563ea1ad4a'),                           │ │
│ │                  │   id=UUID('1ad000dd-edd8-4f8a-ae42-70563ea1ad4a'),                        │ │
│ │                         │   id=UUID('1ad000dd-edd8-4f8a-ae42-70563ea1ad4a'),                 │ │
│ │                    │   id=UUID('1ad000dd-edd8-4f8a-ae42-70563ea1ad4a'),                      │ │
│ │                    │   │   id=UUID('1ad000dd-edd8-4f8a-ae42-70563ea1ad4a'),                  │ │
│ │                  │   id=UUID('1ad000dd-edd8-4f8a-ae42-70563ea1ad4a'),                        │ │
│ │            │   │   id=UUID('1ad000dd-edd8-4f8a-ae42-70563ea1ad4a'),                          │ │
│ │               │   id=UUID('1ad000dd-edd8-4f8a-ae42-70563ea1ad4a'),                           │ │
HTTP Request: GET http://scheduler:8000/tasks/1ad000dd-edd8-4f8a-ae42-70563ea1ad4a "HTTP/1.1 200 OK"
HTTP Request: PATCH http://scheduler:8000/tasks/1ad000dd-edd8-4f8a-ae42-70563ea1ad4a "HTTP/1.1 200 OK"
2025-01-17T08:21:12.824266 [info] Set status to TaskStatus.FAILED in the scheduler for task[id=1ad000dd-edd8-4f8a-ae42-70563ea1ad4a]

Bytes logs seem to concur when grepping for the UUID:

2025-01-17T08:21:09.800620 [info] Added boefje meta [id=1ad000dd-edd8-4f8a-ae42-70563ea1ad4a]
172.30.0.11:57288 - "POST /bytes/raw?boefje_meta_id=1ad000dd-edd8-4f8a-ae42-70563ea1ad4a HTTP/1.1" 200
2025-01-17T08:21:11.894126 [info] Added boefje meta [id=1ad000dd-edd8-4f8a-ae42-70563ea1ad4a]
DETAIL:  Key (id)=(1ad000dd-edd8-4f8a-ae42-70563ea1ad4a) already exists.
DETAIL:  Key (id)=(1ad000dd-edd8-4f8a-ae42-70563ea1ad4a) already exists.
[parameters: {'id': UUID('1ad000dd-edd8-4f8a-ae42-70563ea1ad4a'), 'boefje_id': 'security_txt_downloader', 'boefje_version': None, 'organization': 'test', 'input_ooi': 'Website|internet|185.73.32.3|tcp|80|http|internet|css.underdark.nl', 'arguments': '{"input": {"object_type": "Website", "scan_profile": "scan_profile_type=\'inherited\' reference=Reference(\'Website|internet|185.73.32.3|tcp|80|http| ... (284 characters truncated) ... tcp", "port": "80"}, "service": {"name": "http"}}, "hostname": {"network": {"name": "internet"}, "name": "css.underdark.nl"}, "certificate": "None"}}', 'environment': '{}', 'runnable_hash': '3457f1ec8b651fb4fa6caeedeb70b367cf6d1a6728075648668251d1894cefb1', 'started_at': datetime.datetime(2025, 1, 17, 8, 21, 10, 926257, tzinfo=TzInfo(UTC)), 'ended_at': datetime.datetime(2025, 1, 17, 8, 21, 11, 891491, tzinfo=TzInfo(UTC))}]
DETAIL:  Key (id)=(1ad000dd-edd8-4f8a-ae42-70563ea1ad4a) already exists.
DETAIL:  Key (id)=(1ad000dd-edd8-4f8a-ae42-70563ea1ad4a) already exists.
[parameters: {'id': UUID('1ad000dd-edd8-4f8a-ae42-70563ea1ad4a'), 'boefje_id': 'security_txt_downloader', 'boefje_version': None, 'organization': 'test', 'input_ooi': 'Website|internet|185.73.32.3|tcp|80|http|internet|css.underdark.nl', 'arguments': '{"input": {"object_type": "Website", "scan_profile": "scan_profile_type=\'inherited\' reference=Reference(\'Website|internet|185.73.32.3|tcp|80|http| ... (284 characters truncated) ... tcp", "port": "80"}, "service": {"name": "http"}}, "hostname": {"network": {"name": "internet"}, "name": "css.underdark.nl"}, "certificate": "None"}}', 'environment': '{}', 'runnable_hash': '3457f1ec8b651fb4fa6caeedeb70b367cf6d1a6728075648668251d1894cefb1', 'started_at': datetime.datetime(2025, 1, 17, 8, 21, 10, 926257, tzinfo=TzInfo(UTC)), 'ended_at': datetime.datetime(2025, 1, 17, 8, 21, 11, 891491, tzinfo=TzInfo(UTC))}]

Expected behavior
I'd expect the retries to stop at some point. But most of all, I'd expect the task to try saving its data only once. (perhaps the task was executed twice due to a race condition somehow?

OpenKAT version
Main
@underdarknl underdarknl added the bug Something isn't working label Jan 17, 2025
@github-project-automation github-project-automation bot moved this to Incoming features / Need assessment in KAT Jan 17, 2025
@underdarknl underdarknl changed the title Key constraint issues Key constraint issues, retry / lookup queries forfailed job Jan 17, 2025
@underdarknl underdarknl added the boefjes Issues related to boefjes label Jan 17, 2025
@underdarknl
Copy link
Contributor Author

The interval for each subsequent run is 1 minute:

Stracing the scheduler I see the following:

A call to Octopoes:

GET /test/object?reference=KATFindingType%7CKAT-NO-DNSSEC&valid_time=2025-01-20%2010%3A00%3A40.513421%2B00%3A00

and its results:

{\"object_type\":\"KATFindingType\",\"scan_profile\":{\"scan_profile_type\":\"empty\",\"reference\":\"KATFindingType|KAT-NO-DNSSEC\",\"level\":0,\"user_id\":null},\"user_id\":null,\"primary_key\":\"KATFindingType|KAT-NO-DNSSEC\",\"id\":\"KAT-NO-DNSSEC\",\"description\":\"The provided domain does not have DNSSEC enabled.\",\"source\":\"https://www.dns-school.org/Documentation/dnssec_howto.pdf\",\"impact\":\"DNS requests are not authenticated, thus there is no protection against DNS poisoning or manipulation.\",\"recommendation\":\"Enable DNSSEC on your name servers.\",\"risk_score\":6.9,\"risk_severity\":\"medium\"}

SELECT tasks.id AS tasks_id, tasks.scheduler_id AS tasks_scheduler_id, tasks.schedule_id AS tasks_schedule_id, tasks.type AS tasks_type, tasks.hash AS tasks_hash, tasks.priority AS tasks_priority, tasks.data AS tasks_data, tasks.status AS tasks_status, tasks.created_at AS tasks_created_at, tasks.modified_at AS tasks_modified_at \nFROM tasks \nWHERE tasks.hash = '994b609041a1dd43f4b436d5c668ca57' ORDER BY tasks.created_at DESC \n LIMIT 1

Followed by an SQL resultset
T\0\0\1H\0\ntasks_id\0\0\0B\321\0\1\0\0\v\206\0\20\377\377\377\377\0\0tasks_scheduler_id\0\0\0B\321\0\3\0\0\4\23\377\377\377\377\377\377\0\0tasks_schedule_id\0\0\0B\321\0\n\0\0\v\206\0\20\377\377\377\377\0\0tasks_type\0\0\0B\321\0\t\0\0\4\23\377\377\377\377\377\377\0\0tasks_hash\0\0\0B\321\0\v\0\0\4\23\377\377\0\0\0$\0\0tasks_priority\0\0\0B\321\0\f\0\0\0\27\0\4\377\377\377\377\0\0tasks_data\0\0\0B\321\0\r\0\0\16\332\377\377\377\377\377\377\0\0tasks_status\0\0\0B\321\0\5\0\0B\305\0\4\377\377\377\377\0\0tasks_created_at\0\0\0B\321\0\6\0\0\4\240\0\10\377\377\377\377\0\0tasks_modified_at\0\0\0B\321\0\7\0\0\4\240\0\10\377\377\377\377\0\0D\0\0\1\307\0\n\0\0\0$3b6b06b8-0ebe-4aed-ac17-613842ee61e6\0\0\0\vboefje-test\0\0\0$4e27ab4b-e046-4e8e-be6d-2fe388bc6925\0\0\0\6boefje\0\0\0 994b609041a1dd43f4b436d5c668ca57\0\0\0\3863\0\0\0\332{\"id\": \"3b6b06b8-0ebe-4aed-ac17-613842ee61e6\", \"boefje\": {\"id\": \"kat-finding-types\", \"name\": \"KAT Finding Types\", \"version\": null}, \"input_ooi\": \"KATFindingType|KAT-NO-DNSSEC\", \"dispatches\": [], \"organization\": \"test\"}\0\0\0\tCOMPLETED

followed by a call to bytes:
GET /bytes/boefje_meta?boefje_id=kat-finding-types&input_ooi=KATFindingType%7CKAT-NO-DNSSEC&organization=test&limit=1&descending=true

Followed by a json result:

[{\"id\":\"3b6b06b8-0ebe-4aed-ac17-613842ee61e6\",\"started_at\":\"2025-01-20T08:17:39.131521Z\",\"ended_at\":\"2025-01-20T08:17:39.132199Z\",\"boefje\":{\"id\":\"kat-finding-types\",\"version\":null},\"input_ooi\":\"KATFindingType|KAT-NO-DNSSEC\",\"arguments\":{\"input\":{\"object_type\":\"KATFindingType\",\"scan_profile\":\"scan_profile_type='empty' reference=Reference('KATFindingType|KAT-NO-DNSSEC') level=<ScanLevel.L0: 0> user_id=None\",\"user_id\":\"None\",\"primary_key\":\"KATFindingType|KAT-NO-DNSSEC\",\"id\":\"KAT-NO-DNSSEC\",\"description\":\"The provided domain does not have DNSSEC enabled.\",\"source\":\"https://www.dns-school.org/Documentation/dnssec_howto.pdf\",\"impact\":\"DNS requests are not authenticated, thus there is no protection against DNS poisoning or manipulation.\",\"recommendation\":\"Enable DNSSEC on your name servers.\",\"risk_score\":6.9,\"risk_severity\":\"medium\"}},\"organization\":\"test\",\"runnable_hash\":\"6bf86cba90b9113aa883db9761781a1b37c89f0376c5d0098b208f88326461e4\",\"environment\":{}}]

@underdarknl
Copy link
Contributor Author

Image
The object in my first batch of logs is now (again) the only object repeatedly being queried. There is one 'running' job, that obviously failed but never got closed.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
boefjes Issues related to boefjes bug Something isn't working
Projects
KAT
Status: Incoming features / Need assessment
Milestone
No milestone
Development

No branches or pull requests
1 participant
@underdarknl