Stream mode causes ERROR 500 - Internal Server Error!

[cRUSHr2012]

Hello, I've noticed there's a problem when using STREAM mode. I receive HTTP 500 ERROR when activating STREAM mode.

Debian version 11.3 PHP version : 7.4.29 Crowdsec version : 1.4.3 WP Crowdsec plugin : 1.10.0 Wordpress version : 6.1.1

I've changed the port for crowdsec in /etc/crowdsec/config.yaml in 8888 because 8080 is already used.

This issue is happening with / without the option "Use cURL to call Local API"

With Use cURL to call Local API enabled I have this in my logs.

The Crowdec WP plugin debug.log is:

==> ../../../debug.log <==
[14-Dec-2022 21:46:13 UTC] PHP Fatal error:  Uncaught CrowdSecBouncer\BouncerException: Unexpected CURL call failure: Operation timed out after 1000 milliseconds with 0 bytes received in /var/www/clients/client0/web24/web/blog/wp-content/plugins/crowdsec/vendor/crowdsec/bouncer/src/RestClient/Curl.php:35
Stack trace:
#0 /var/www/clients/client0/web24/web/blog/wp-content/plugins/crowdsec/vendor/crowdsec/bouncer/src/ApiClient.php(94): CrowdSecBouncer\RestClient\Curl->request()
#1 /var/www/clients/client0/web24/web/blog/wp-content/plugins/crowdsec/vendor/crowdsec/bouncer/src/ApiCache.php(181): CrowdSecBouncer\ApiClient->getStreamedDecisions()
#2 /var/www/clients/client0/web24/web/blog/wp-content/plugins/crowdsec/vendor/crowdsec/bouncer/src/Bouncer.php(299): CrowdSecBouncer\ApiCache->warmUp()
#3 /var/www/clients/client0/web24/web/blog/wp-content/plugins/crowdsec/inc/admin/advanced-settings.php(21): CrowdSecBouncer\Bouncer->warmBlocklistCacheUp()
#4 /var/www/clients/client0/web24/web/blog/wp-content/plugins/crowdsec/inc/admin/init.php(248): {closure}()
#5 /v in /var/www/clients/client0/web24/web/blog/wp-content/plugins/crowdsec/vendor/crowdsec/bouncer/src/RestClient/Curl.php on line 35

The /var/log/crowdsec.log show:

==> /var/log/crowdsec.log <==
time="14-12-2022 23:46:13" level=warning msg="client 127.0.0.1 disconnected : write tcp 127.0.0.1:8888->127.0.0.1:51036: write: broken pipe"

The /var/log/crowdsec_api.log shows:

==> /var/log/crowdsec_api.log <==
time="14-12-2022 23:46:13" level=info msg="127.0.0.1 - [Wed, 14 Dec 2022 23:46:13 EET] \"GET /v1/decisions/stream?startup=true&scopes=Ip%2CRange HTTP/1.1 200 1.316249051s \"WordPress CrowdSec Bouncer/v1.10.0\" \""

With With Use cURL to call Local API disabled I have this in my logs:

The Crowdec WP plugin debug.log is:

==> ../../../debug.log <==
[14-Dec-2022 21:54:58 UTC] PHP Warning:  file_get_contents(http://127.0.0.1:8888/v1/decisions/stream?startup=true&amp;scopes=Ip%2CRange): failed to open stream: HTTP request failed! in /var/www/clients/client0/web24/web/blog/wp-content/plugins/crowdsec/vendor/crowdsec/bouncer/src/RestClient/FileGetContents.php on line 50
[14-Dec-2022 21:54:58 UTC] PHP Fatal error:  Uncaught CrowdSecBouncer\BouncerException: Unexpected HTTP call failure. in /var/www/clients/client0/web24/web/blog/wp-content/plugins/crowdsec/vendor/crowdsec/bouncer/src/RestClient/FileGetContents.php:52
Stack trace:
#0 /var/www/clients/client0/web24/web/blog/wp-content/plugins/crowdsec/vendor/crowdsec/bouncer/src/ApiClient.php(94): CrowdSecBouncer\RestClient\FileGetContents->request()
#1 /var/www/clients/client0/web24/web/blog/wp-content/plugins/crowdsec/vendor/crowdsec/bouncer/src/ApiCache.php(181): CrowdSecBouncer\ApiClient->getStreamedDecisions()
#2 /var/www/clients/client0/web24/web/blog/wp-content/plugins/crowdsec/vendor/crowdsec/bouncer/src/Bouncer.php(299): CrowdSecBouncer\ApiCache->warmUp()
#3 /var/www/clients/client0/web24/web/blog/wp-content/plugins/crowdsec/inc/admin/advanced-settings.php(21): CrowdSecBouncer\Bouncer->warmBlocklistCacheUp()
#4 /var/www/clients/client0/web24/web/blog/wp-content/plugins/crowdsec/inc/admin/init.php(248): {closure}()
#5 /var/www/clients/client0/web24/web/blog/wp-inc in /var/www/clients/client0/web24/web/blog/wp-content/plugins/crowdsec/vendor/crowdsec/bouncer/src/RestClient/FileGetContents.php on line 52

curl on http://127.0.0.1:8888 shows:

curl "http://127.0.0.1:8888/v1/decisions/stream?startup=true&scopes=Ip%2CRange"
{"message":"access forbidden"}

I assume it's normal, because it's expecting a header with the bouncer key. Can you give me an example of a curl request with all the needed headers to query in STREAM mode ? I assume the response it gets is different from what is expected.

Test your settings -> Test bouncing works. I've tried Bouncing level Normal / Flex, no change. I've tried caching with Filesystem / Redis, still no change. I've deleted and recreated the bouncer API key, still no change.

[cRUSHr2012]

I've tested older versions of the plugin 1.9.0 and 1.8.0, they behave the same, with 500 Error. I think the response for the GET /v1/decisions/stream?startup=true&scopes=Ip%2CRange is different now (or maybe bigger) I found in the documentation how to query the API, this is the beginning for the response:

curl  -s -H "X-Api-Key: ***"  http://localhost:8888/v1/decisions/stream\?startup\=true | jq . | more
{
  "deleted": [
    {
      "duration": "-165h28m44.900234679s",
      "id": 40293718,
      "origin": "CAPI",
      "scenario": "crowdsecurity/http-open-proxy",
      "scope": "Ip",
      "type": "ban",
      "value": "51.79.177.125"
    },
    {
      "duration": "-165h28m44.900255228s",
      "id": 40293719,
      "origin": "CAPI",
      "scenario": "crowdsecurity/http-backdoors-attempts",
      "scope": "Ip",
      "type": "ban",
      "value": "20.193.142.38"
    },
...

[julienloizelet]

Hi, Thanks for your message.

I just tested with quite the same conditions (php 7.4, crowdsec 1.4.3, WP 6.1.1 and plugin 1.1.10) and was unable to reproduce.

I guess there is something with the custom port, but we'll have to investigate a little bit. (I did not try with a custom port for now)

Just for information, when you activate the stream mode, the cache has to be warm up : this is why there is an automatic call to the v1/decisions/stream\?startup=true URI. But in your case, it seems that this call fails, and we have to find out why ...

First thing I notice is that your direct curl test use the http://localhost URL, while it seems that the URL in the plugin is set to http://127.0.0.1 : Could you please try to set http://localhost in the plugin too ? I see no reason why it could be an issue, but it is worth checking, I guess.

The other question I have would be ; does it work when the Stream mode is NOT enabled (a.k.a. live mode) ? (you could look the debug.log to see is all works as expected). It would be very strange if it works in live mode but not in stream mode as the same kind of call are made.

Last thing, I see a strange line in your /var/log/crowdsec.log : write tcp 127.0.0.1:8888->127.0.0.1:51036 : does it mean that you have some kind of redirect from port 8888 to port 51036 ? Maybe this is not important, but I am just trying to understand.

Thanks

p.s :

Test your settings -> Test bouncing works.

Please be sure to save the settings before clicking the 'Test' button, as only the saved settings are tested.

[julienloizelet]

Hi,

I just found that you maybe have to modify 2 files if you need a custom port : https://github.com/crowdsecurity/crowdsec/issues/552#issuecomment-1185361489

I am not sure if this comment is up-to-date, but maybe your bug is related. Could you check if the /etc/crowdsec/local_api_credentials.yaml is also modified ?

Thanks

[cRUSHr2012]

Hi, If you remember, i am the one that tested crowdsec with multiple wordpress sites and the same redis DB, with stream mode. This is the same server, that received only Debian / ISPConfig updates.

First :/etc/crowdsec/local_api_credentials.yamlhas also port 8888 changed in it.

Second : changing localhost with 127.0.0.1 makes no difference.

Third :/var/log/crowdsec.log : write tcp 127.0.0.1:8888->127.0.0.1:51036. 51036 is the source port for the request. It's made from localhost:51036 to localhost:8888. Because of the error, I assume PHP tries to respond but the connection is now closed. I can see port numbers in the logs, in netstat briefly.

Fourth : In LIVE mode, all works OK. I can see it in the logs.

I have outputed the result of the curl in a file, it it 5.2MB large. I assume it's normal. curl -s -H "X-Api-Key: ********" http://localhost:8888/v1/decisions/stream\?startup\=true\&scopes\=Ip,Range > out.txt

I also changed 8080 that ISPConfig uses to another port and used 8888 in the 2 crowdsec config files. Still the same.

Indeed something happens when it needs to warm the cache. I remember that the initial warm took 35 seconds (i had to increase the PHP timeout beyond 30sec). Now it dies after ~2 seconds.

[julienloizelet]

Hi,

thanks for your answers (yes, I remember :) ).

Ok, so it seems that your issue is due to the size of the decisions you retrieve on warm up : maybe it takes too much time (timeout issue) or this is really a response size issue.

Considering the timeout, could you please try to edit manually a file in the plugin sources ?

We will try to increase the timeout value for Curl (so you will have to test with Use Curl set to true).

To do that, please look at the file vendor/crowdsec/bouncer/src/RestClient/Curl.php and, starting at line 109, replace :

if ($this->timeout > 0) {
    $options[\CURLOPT_TIMEOUT] = $this->timeout;
}

by

//if ($this->timeout > 0) {
      $options[\CURLOPT_TIMEOUT] = XX;
//}

where XX could be 30, or 60, or more (this the timeout value in seconds).

Hope it could resolve your issue : if yes, I will add a configuration setting for a custom timeout. If not, I will have to manage how to handle response with big size like (e.g > 5MB)

Please, let me know.

Thanks

[cRUSHr2012]

This works. But Use cURL to call Local API must be set.

2022-12-15T09:39:11.954143+00:00|200|{"type":"CACHE_WARMED_UP","added_decisions":28584}
2022-12-15T09:39:11.970447+00:00|200|{"type":"WP_SETTING_UPDATE","crowdsec_stream_mode":true}

As the stream mode is enabled, the cache has just been warmed up, there are now 28584 decisions in cache.

[julienloizelet]

Nice,

Can you tell me with which value of timeout you succeed ? And maybe how many times it takes between the "START_CACHE_WARMUP" and "CACHE_WARMED_UP" if you look at the debug.log file (just before the 2 lines you pasted).

To test without Use Curl, you should modify another file : vendor/crowdsec/bouncer/src/RestClient/FileGetContents.php At line 92, you could replace

'timeout' => $timeout ?: $this->timeout,

by

'timeout' => XX,

Well, what I will do now is working on a way to add a new setting lapi_timeout, so that you could modify the value directly in the WordPress admin. I will try to add this in a next release asap.

Thanks

[cRUSHr2012]

I used 100 as a number of seconds.

It takes about 33 seconds.

2022-12-15T12:44:57.900764+00:00|100|{"type":"START_CACHE_WARMUP"} 2022-12-15T12:45:30.005004+00:00|200|{"type":"CACHE_WARMED_UP","added_decisions":28619}

You could add "Warming up the cache took X seconds, after As the stream mode is enabled, the cache has just been warmed up, there are now 28584 decisions in cache."

[julienloizelet]

Hi,

I just released a new 1.11.0 version of the plugin : the timeout can now be modified in settings and the default timeout value has been increased from 1 second to 120 seconds.

Thanks