Gunicorn [CRITICAL] WORKER TIMEOUT

[FreakyFreddie]

Environment:

• CTFd Version/Commit: Latest as of 11/11/2017
• Operating System: Ubuntu 16.04 LTS, deploying platform in Docker containers, using docker-compose up
• Web Browser and Version: Firefox: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:56.0) Gecko/20100101 Firefox/56.0 and Chrome: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/61.0.3163.100 Safari/537.36

What happened?
Seeing a lot of Gunicorn [CRITICAL] WORKER TIMEOUT entries in the error.log file. I do not fully understand what this means. I think it happened around the time the application stopped responding. I had to reboot the containers to fix the issue.

Any thoughts?

Any associated stack traces or error logs
Error.log

[2017-11-13 14:05:10 +0000] [216] [CRITICAL] WORKER TIMEOUT (pid:252)
[2017-11-13 14:05:10 +0000] [252] [INFO] Worker exiting (pid: 252)
[2017-11-13 14:05:10 +0000] [265] [INFO] Booting worker with pid: 265
[2017-11-13 14:05:41 +0000] [216] [CRITICAL] WORKER TIMEOUT (pid:265)
[2017-11-13 14:05:41 +0000] [265] [INFO] Worker exiting (pid: 265)
[2017-11-13 14:05:41 +0000] [278] [INFO] Booting worker with pid: 278
[2017-11-13 14:06:12 +0000] [216] [CRITICAL] WORKER TIMEOUT (pid:278)
[2017-11-13 14:06:12 +0000] [278] [INFO] Worker exiting (pid: 278)
[2017-11-13 14:06:12 +0000] [291] [INFO] Booting worker with pid: 291
[2017-11-13 14:06:43 +0000] [216] [CRITICAL] WORKER TIMEOUT (pid:291)
[2017-11-13 14:06:43 +0000] [291] [INFO] Worker exiting (pid: 291)
[2017-11-13 14:06:43 +0000] [304] [INFO] Booting worker with pid: 304
[2017-11-13 14:07:14 +0000] [216] [CRITICAL] WORKER TIMEOUT (pid:304)
[2017-11-13 14:07:14 +0000] [304] [INFO] Worker exiting (pid: 304)
[2017-11-13 14:07:14 +0000] [317] [INFO] Booting worker with pid: 317
[2017-11-13 14:07:45 +0000] [216] [CRITICAL] WORKER TIMEOUT (pid:317)
[2017-11-13 14:07:45 +0000] [317] [INFO] Worker exiting (pid: 317)
[2017-11-13 14:07:46 +0000] [330] [INFO] Booting worker with pid: 330
[2017-11-13 14:08:17 +0000] [216] [CRITICAL] WORKER TIMEOUT (pid:330)
[2017-11-13 14:08:17 +0000] [330] [INFO] Worker exiting (pid: 330)
[2017-11-13 14:08:17 +0000] [343] [INFO] Booting worker with pid: 343
[2017-11-13 14:08:48 +0000] [216] [CRITICAL] WORKER TIMEOUT (pid:343)
[2017-11-13 14:08:48 +0000] [343] [INFO] Worker exiting (pid: 343)
[2017-11-13 14:08:48 +0000] [356] [INFO] Booting worker with pid: 356
[2017-11-13 14:09:19 +0000] [216] [CRITICAL] WORKER TIMEOUT (pid:356)
[2017-11-13 14:09:19 +0000] [356] [INFO] Worker exiting (pid: 356)
[2017-11-13 14:09:19 +0000] [369] [INFO] Booting worker with pid: 369
[2017-11-13 14:09:50 +0000] [216] [CRITICAL] WORKER TIMEOUT (pid:369)
[2017-11-13 14:09:50 +0000] [369] [INFO] Worker exiting (pid: 369)
[2017-11-13 14:09:50 +0000] [382] [INFO] Booting worker with pid: 382
[2017-11-13 14:10:21 +0000] [216] [CRITICAL] WORKER TIMEOUT (pid:382)
[2017-11-13 14:10:21 +0000] [382] [INFO] Worker exiting (pid: 382)
[2017-11-13 14:10:21 +0000] [395] [INFO] Booting worker with pid: 395
[2017-11-13 14:10:52 +0000] [216] [CRITICAL] WORKER TIMEOUT (pid:395)
[2017-11-13 14:10:52 +0000] [395] [INFO] Worker exiting (pid: 395)
[2017-11-13 14:10:52 +0000] [408] [INFO] Booting worker with pid: 408
[2017-11-13 14:11:23 +0000] [216] [CRITICAL] WORKER TIMEOUT (pid:408)
[2017-11-13 14:11:23 +0000] [408] [INFO] Worker exiting (pid: 408)
[2017-11-13 14:11:23 +0000] [421] [INFO] Booting worker with pid: 421
[2017-11-13 14:11:54 +0000] [216] [CRITICAL] WORKER TIMEOUT (pid:421)
[2017-11-13 14:11:54 +0000] [421] [INFO] Worker exiting (pid: 421)
[2017-11-13 14:11:55 +0000] [434] [INFO] Booting worker with pid: 434
[2017-11-13 14:12:26 +0000] [216] [CRITICAL] WORKER TIMEOUT (pid:434)
[2017-11-13 14:12:26 +0000] [434] [INFO] Worker exiting (pid: 434)
[2017-11-13 14:12:26 +0000] [447] [INFO] Booting worker with pid: 447

Access.log

10.0.4.45 - - [13/Nov/2017:14:03:25 +0000] "GET /chals/solves HTTP/1.1" 200 3 "https://10.0.7.4/challenges" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/62.0.3202.89 Safari/537.36"

10.0.4.214 - - [13/Nov/2017:14:04:21 +0000] "GET / HTTP/1.0" 200 2950 "-" "-"

10.0.4.2 - - [13/Nov/2017:14:12:26 +0000] "GET / HTTP/1.1" 200 2950 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/61.0.3163.100 Safari/537.36"

Error.log

[2017-11-13 14:42:51 +0000] [216] [CRITICAL] WORKER TIMEOUT (pid:460)
[2017-11-13 14:42:51 +0000] [460] [INFO] Worker exiting (pid: 460)
[2017-11-13 14:42:51 +0000] [473] [INFO] Booting worker with pid: 473
[2017-11-13 14:43:22 +0000] [216] [CRITICAL] WORKER TIMEOUT (pid:473)
[2017-11-13 14:43:22 +0000] [473] [INFO] Worker exiting (pid: 473)
[2017-11-13 14:43:22 +0000] [486] [INFO] Booting worker with pid: 486
[2017-11-13 14:43:53 +0000] [216] [CRITICAL] WORKER TIMEOUT (pid:486)
[2017-11-13 14:43:53 +0000] [486] [INFO] Worker exiting (pid: 486)
[2017-11-13 14:43:53 +0000] [499] [INFO] Booting worker with pid: 499
[2017-11-13 14:44:24 +0000] [216] [CRITICAL] WORKER TIMEOUT (pid:499)
[2017-11-13 14:44:24 +0000] [499] [INFO] Worker exiting (pid: 499)
[2017-11-13 14:44:24 +0000] [512] [INFO] Booting worker with pid: 512
[2017-11-13 14:44:55 +0000] [216] [CRITICAL] WORKER TIMEOUT (pid:512)
[2017-11-13 14:44:55 +0000] [512] [INFO] Worker exiting (pid: 512)
[2017-11-13 14:44:55 +0000] [525] [INFO] Booting worker with pid: 525
[2017-11-13 14:45:26 +0000] [216] [CRITICAL] WORKER TIMEOUT (pid:525)
[2017-11-13 14:45:26 +0000] [525] [INFO] Worker exiting (pid: 525)
[2017-11-13 14:45:26 +0000] [538] [INFO] Booting worker with pid: 538
[2017-11-13 14:45:57 +0000] [216] [CRITICAL] WORKER TIMEOUT (pid:538)
[2017-11-13 14:45:57 +0000] [538] [INFO] Worker exiting (pid: 538)
[2017-11-13 14:45:57 +0000] [551] [INFO] Booting worker with pid: 551
[2017-11-13 14:46:29 +0000] [216] [CRITICAL] WORKER TIMEOUT (pid:551)
[2017-11-13 14:46:29 +0000] [551] [INFO] Worker exiting (pid: 551)
[2017-11-13 14:46:29 +0000] [564] [INFO] Booting worker with pid: 564
[2017-11-13 14:47:00 +0000] [216] [CRITICAL] WORKER TIMEOUT (pid:564)
[2017-11-13 14:47:00 +0000] [564] [INFO] Worker exiting (pid: 564)
[2017-11-13 14:47:00 +0000] [577] [INFO] Booting worker with pid: 577
[2017-11-13 14:47:31 +0000] [216] [CRITICAL] WORKER TIMEOUT (pid:577)
[2017-11-13 14:47:31 +0000] [577] [INFO] Worker exiting (pid: 577)
[2017-11-13 14:47:31 +0000] [590] [INFO] Booting worker with pid: 590

Access.log

10.0.4.110 - - [13/Nov/2017:14:42:20 +0000] "GET /themes/original/static/js/vendor/handlebars.min.js HTTP/1.1" 200 75510 "https://10.0.7.4/" "Mozilla/5.0 (X11; Linux x86_64; rv:52.0) Gecko/20100101 Firefox/52.0"

10.0.4.129 - - [13/Nov/2017:14:47:32 +0000] "GET / HTTP/1.1" 200 2917 "-" "Mozilla/5.0 (X11; Linux x86_64; rv:52.0) Gecko/20100101 Firefox/52.0"

[ColdHeat]

As I mentioned in #467 I think this is primarily a network connectivity issue. IIRC, SQLAlchemy in CTFd attempts to keep a couple connections to the database alive. A disruption in network service that happens at the right time could cause some issues with CTFd itself and gunicorn.

If you can find something that causes this to happen consistently, it would go a long way.

Also how did you deploy this CTFd instance?

[FreakyFreddie]

I just deployed it using the docker-compose.yml file. You are probably right about the network connectivity issue. I will test again next monday and notify you of the results.

[tghosth]

Hi @FreakyFreddie did you find any way of solving this? I appear to have the same problem.

I am also using this version of Ubuntu, doing it in an EC2 and using the docker-compose method to create two containers.

@ColdHeat this is the issue I talking about on slack here.

I followed the docker install instructions from here, the docker-compose instructions from here and the CTFd deploy instructions here

When I run docker version I get this:

Client:
 Version:       17.12.0-ce
 API version:   1.35
 Go version:    go1.9.2
 Git commit:    c97c6d6
 Built: Wed Dec 27 20:11:19 2017
 OS/Arch:       linux/amd64

Server:
 Engine:
  Version:      17.12.0-ce
  API version:  1.35 (minimum version 1.12)
  Go version:   go1.9.2
  Git commit:   c97c6d6
  Built:        Wed Dec 27 20:09:53 2017
  OS/Arch:      linux/amd64
  Experimental: false

[tghosth]

In the meantime, I stopped using Docker and instead used the instructions here (thanks @ColdHeat 😄) changing serve.py to be host=0.0.0.0 to allow external connections and Debug=False).

Even though it using sqllite, it still seems to work okay so I will probably stick to that for now although it would be good if someone figured out why the docker option doesn't seem to work well.