HTTP 500 (max execution time exceeded) when searching for not limited events

[dawid-czarnecki]

HTTP 500 (max execution time exceeded) when searching for not limited events

Hi,

I've got a problem. I try to download events which are unpublished through api/pymisp. Unfortunately the script terminates with HTTP 500 (max execution time exceeded). With curl and REST API result is the same as with pymisp.
I noticed the same happens when search is not limited by some time for example 1d. If there is last=1d, then misp process for a while but return results.
Does anyone know why this might happen?
Here are some details:

Directly in the database, results goes immediately (X is more than 0):

select * from events where published=0;
...
X rows in set (0.00 sec)

Work environment

Questions	Answers
Type of issue	Bug, Question
OS version (server)	RedHat
OS version (client)	RedHat
PHP version	7.1.6
MISP version / git hash	2.4.76
phpinfo max_execution_time	200
phpinfo memory_limit	2048M

Expected behavior

List of unpublished events in json.

Actual behavior

requests.exceptions.HTTPError: 500 Server Error: Internal Server Error for url: https://localhost/events/restSearch/download

Steps to reproduce the behavior

script.py:

from pymisp import PyMISP
url = "https://localhost"
key = "xxx"
pymisp = PyMISP(url, key)
p = pymisp.search('events',published = 0)
print(p)

python script.py

Logs, screenshots, configuration dump, ...

misp.local_access.log:

::1 (::1) [25/Aug/2017:10:52:20 +0200] "POST /events/restSearch/download HTTP/1.1" 500 125 "PyMISP 2.4.71 - Python 2.7.5" "-" with XXX
::1 (::1) [25/Aug/2017:11:02:34 +0200] "POST /events/restSearch/download HTTP/1.1" 500 125 "PyMISP 2.4.71 - Python 3.5.1" "-" with XXX

app/tmp/logs/error.log:

2017-08-25 08:55:41 Error: Fatal Error (1): Maximum execution time of 200 seconds exceeded in [/XXX/app/Controller/EventsController.php, line 2640]
2017-08-25 08:55:41 Error: [InternalErrorException] Internal Server Error
Request URL: /events/restSearch/download
Stack Trace:
#0 /XXX/app/Lib/cakephp/lib/Cake/Error/ErrorHandler.php(212): ErrorHandler::handleFatalError(1, 'Maximum executi...', '/XXX/a...', 2640)
#1 /XXX/app/Lib/cakephp/lib/Cake/Core/App.php(970): ErrorHandler::handleError(1, 'Maximum executi...', '/XXX/a...', 2640, Array)
#2 /XXX/app/Lib/cakephp/lib/Cake/Core/App.php(943): App::_checkFatalError()
#3 [internal function]: App::shutdown()
#4 {main}
2017-08-25 09:05:55 Error: Fatal Error (1): Maximum execution time of 200 seconds exceeded in [/XXX/app/Controller/EventsController.php, line 2640]
2017-08-25 09:05:55 Error: [InternalErrorException] Internal Server Error
Request URL: /events/restSearch/download
Stack Trace:
#0 /XXX/app/Lib/cakephp/lib/Cake/Error/ErrorHandler.php(212): ErrorHandler::handleFatalError(1, 'Maximum executi...', '/XXX/a...', 2640)
#1 /XXX/app/Lib/cakephp/lib/Cake/Core/App.php(970): ErrorHandler::handleError(1, 'Maximum executi...', '/XXX/a...', 2640, Array)
#2 /XXX/app/Lib/cakephp/lib/Cake/Core/App.php(943): App::_checkFatalError()
#3 [internal function]: App::shutdown()
#4 {main}

[iglocska]

First of all make sure you upgrade your MISP, there have been a lot of improvements since 2.4.71 that deal with performance / export memory usage etc.

Not setting any filters means that you are dealing with a massive amount of data that is being prepared and returned to you (as well as being looped through all the ACL, export modifications, etc). Make sure that you have enough memory available for PHP and that your MySQL is optimised. Also make sure that you increase the execution time if it's too low.

Could you share the settings that you are using currently? Also, most importantly, make sure you update first! :)

[cristianbell]

max_execution_time for PHP and also the web server timeout if you didn't change the setup.
Though it should be higher than the 200 you mentioned as max_exec_time..

[dawid-czarnecki]

@iglocska
I know it is not the newest version of misp but it shouldn’t work that long even on older version. Grabbing data directly from database works much faster. I can imagine there are some preparation process in place in the misp core but the amount of returned events is below 100.

As you can see memory for php is set to 2G which is way too much. Php-fpm consumes not more than 5% of memory but 100% CPU instead.

What settings do you asking for? I don’t want to set any additional filters, just all unpublished events.

@cristianbell
It was 1600 before and the situation was exactly the same besides that script worked above 20 minutes.

[iglocska]

Your database call is only fetching the event though ;)

The api call will fetch:
Event, Attribute, ShadowAttribute, EventTag, Tag, AttributeTag, Correlation, FeedCorrelation, Whitelist, Warninglist, SharingGroup, SharingGroupServer, Server, SharingGroupOrganisation, Organisation, EventBlacklist, Whitelist.

All of this while filtering all of the data-points based on your ACL that is build using your user account, organisation, sharing groups, etc, with export modifications done to the data.

Then we didn't talk about the samples yet.

It's really not something you can compare ;) 2G for php is not too much, the data set in itself that you are exporting in raw JSON is probably close larger than 2G alone if you don't set any filters.

As for the CPU usage, that is probably due to disk reads blocking IO, which will show up as high CPU usage - or alternatively an untuned MySQL that runs out of memory.

[iglocska]

Dawid, maybe we should set up a conf call and cover some basics, if you're up for it sometime ;)

[iglocska]

Also, could you send us the exact query that caused the issue? I tried it on our instance and fetching all unpublished events took me around 580 ms, so something fishy is going on. Sure the parameter was set correctly? If MISP finds no valid filters it will just return everything unfiltered, which could be massive.

[elhoim]

@dawid-czarnecki an idea to try is to run the iostat tool to get an idea of wait time for io requests (r_await and w_await). Some details are available at: https://www.computerhope.com/unix/iostat.htm
This should give you an idea of the waiting time due to your IO subsystem.

[adulau]

Pagination has been implemented in the API (2.4.96 and upper). You can now do such query via restSearch (events or/and attributes level):

{
    "returnFormat": "json",
    "last": "1d",
    "page": 1,
    "limit": 5
}

Documentation is the following (available via MISP):

• limit Limit the number of results returned, depending on the scope (for example 10 attributes or 10 full events).
• page If a limit is set, sets the page to be returned. page 3, limit 100 will return records 201->300).

Could you test if this solves your issues? and reopen the issue if not. Thanks a lot.

[droe]

Just fixed a problem with the same symptoms (status 500 in response to restSearch with large result) by using pagination. Also resulted in a roughly 4x speed-up.