PHP-FPM via FastCGI throws 502 Bad Gateway after 10 Requests

I have go1.7-caddy-0.9.2 installed on NixOS 16.09 (GNU/Linux) and configured PHP 5.6 (FPM handler).

When i open the website in my browser (Chromium 55 on OS X), i get normal responses for the first 10 requests after i restarted Caddy.

But then i start to get random files like JavaScript/CSS or a 1x1 tracking pixel. Some times files get downloaded that contain parts of JS librarys. Or “File not found.” and “502 Bad Gateway”

I have this error with a Piwik install and also with this DokuWiki (that is every PHP i have):

https://davidak.de/gna/doku.php

I also get that responses with a phpinfo(); where no if that ressources are loaded!

https://davidak.de/gna/info.php

I have tested the same PHP-Socket with Nginx without any problem (even without restarting it), so i think this is related to Caddy. Maybe it is a bug or i do something wrong.

Also no problems with Caddy serving static sites.

Have you ever seen this behaviour?

/var/www/gnaclan/web/Caddyfile

davidak.de/gna {
  root /var/www/gnaclan/web
  gzip

  internal /forbidden
  rewrite {
    r /(data/|conf/|bin/|inc/|install.php)
    to /forbidden
  }

    rewrite /_media {
        r (.*)
        to /lib/exe/fetch.php?media={1}
    }

#  rewrite /_media {
#    to /lib/exe/fetch.php?media={path}&{query}
#  }
  rewrite /_detail {
    to /lib/exe/detail.php?media={path}&{query}
  }
  rewrite /_export {
    r /([^/]+)/(.*)
    to /doku.php?do=export_{1}&id={2}
  }
  rewrite {
    if {path} not_match /lib/.*
    if {path} not_match /forbidden
    r /(.*)
    to {uri} /doku.php?id={1}&{query}
  }

  log /var/www/gnaclan/log/access.log {
    rotate {
      age 96
      keep 10
    }
  }

  errors {
    log /var/www/gnaclan/log/error.log {
      age 96
      keep 10
    }
  }

#  fastcgi / 127.0.0.1:9001 php
  fastcgi / unix:/run/phpfpm/gnaclan.sock php
}

I have not increased file descriptors yet but it’s using currently 33.

Feb 08 00:30:27 atomic caddy[17410]: WARNING: File descriptor limit 1024 is too low for production servers. At least 8192 is recommended. Fix with "ulimit -n 8192".

/var/www/gnaclan/log/error.log

08/Feb/2017:00:27:43 +0100 [ERROR 502 /lib/exe/js.php] malformed MIME header line: t; var target = e.target || e.srcElement;
08/Feb/2017:00:27:43 +0100 [ERROR 502 /lib/exe/indexer.php] malformed MIME header line: ,DWgetSelection(field).start)]; if (field.form.prefix) { // we need to look in prefix context opts.push(field.form.prefix.value); }
08/Feb/2017:00:27:48 +0100 [ERROR 502 /lib/exe/js.php] malformed MIME header line: }
08/Feb/2017:00:27:48 +0100 [ERROR 502 /lib/exe/indexer.php] http2: stream closed
08/Feb/2017:00:27:48 +0100 [ERROR 502 /lib/exe/js.php] malformed MIME header line: t; var target = e.target || e.srcElement;
08/Feb/2017:00:27:49 +0100 [ERROR 502 /lib/exe/indexer.php] malformed MIME header line: ,DWgetSelection(field).start)]; if (field.form.prefix) { // we need to look in prefix context opts.push(field.form.prefix.value); }
08/Feb/2017:00:59:20 +0100 [ERROR 502 /lib/exe/indexer.php] malformed MIME header line: }
08/Feb/2017:00:59:25 +0100 [ERROR 502 /lib/exe/indexer.php] http2: stream closed
08/Feb/2017:00:59:25 +0100 [ERROR 502 /lib/exe/indexer.php] malformed MIME header line: ;
08/Feb/2017:01:01:16 +0100 [ERROR 502 /feed.php] fcgi: invalid header version

var target = e.target || e.srcElement; is from lib/scripts/fileuploader.js
Selection(field).start)]; if (field.form.prefix) { // we need to look in prefix context is from lib/scripts/edit.js:

/**
 * Determine the current section level while editing
 *
 * @param {string} textboxId   ID of the text field
 *
 * @author Andreas Gohr <gohr@cosmocode.de>
 */
function currentHeadlineLevel(textboxId){
    var field = jQuery('#' + textboxId)[0],
        s = false,
        opts = [field.value.substr(0,DWgetSelection(field).start)];
    if (field.form.prefix) {
        // we need to look in prefix context
        opts.push(field.form.prefix.value);
    }

So random lines of code from the webroot get’s served as HEADER or HTTP response. When this is a PHP-Script that contains sensitive information like database credentials it is a serious security issue!

Here is a strace from a request where i got “502 Bad Gateway”:

strace: Process 1935 attached with 16 threads
[pid  4665] futex(0xc4203a4510, FUTEX_WAIT, 0, NULL <unfinished ...>
[pid  4661] futex(0xc4203dd110, FUTEX_WAIT, 0, NULL <unfinished ...>
[pid  1940] futex(0xc4200ee110, FUTEX_WAIT, 0, NULL <unfinished ...>
[pid  1939] futex(0xc420028d10, FUTEX_WAIT, 0, NULL <unfinished ...>
[pid  1938] futex(0xd52ac0, FUTEX_WAIT, 0, NULL <unfinished ...>
[pid  4662] epoll_wait(4,  <unfinished ...>
[pid  1942] futex(0xc4203dc910, FUTEX_WAIT, 0, NULL <unfinished ...>
[pid  1941] futex(0xc420029d10, FUTEX_WAIT, 0, NULL <unfinished ...>
[pid  4660] futex(0xc4200ef110, FUTEX_WAIT, 0, NULL <unfinished ...>
[pid  4663] futex(0xc4200efd10, FUTEX_WAIT, 0, NULL <unfinished ...>
[pid  4664] restart_syscall(<... resuming interrupted futex ...> <unfinished ...>
[pid  4659] futex(0xc4203dc510, FUTEX_WAIT, 0, NULL <unfinished ...>
[pid  3954] futex(0xc4200ee910, FUTEX_WAIT, 0, NULL <unfinished ...>
[pid  1937] restart_syscall(<... resuming interrupted futex ...> <unfinished ...>
[pid  1943] futex(0xc4200ee510, FUTEX_WAIT, 0, NULL <unfinished ...>
[pid  1935] futex(0xd363d0, FUTEX_WAIT, 0, NULL <unfinished ...>
[pid  4662] <... epoll_wait resumed> [{EPOLLIN|EPOLLOUT, {u32=3482463272, u64=139839027686440}}], 128, -1) = 1
[pid  4662] futex(0xd35738, FUTEX_WAKE, 1) = 1
[pid  1937] <... restart_syscall resumed> ) = 0
[pid  1937] sched_yield( <unfinished ...>
[pid  4662] read(27, "\27\3\3\0B\0\0\0\0\0\0\0X\202\351\201u\315\227\243C\r\320\3\344yB\210u\17\255\345"..., 1024) = 117
[pid  4662] futex(0xc4203dc910, FUTEX_WAKE, 1) = 1
[pid  1942] <... futex resumed> )       = 0
[pid  1942] epoll_wait(4, [], 128, 0)   = 0
[pid  1942] select(0, NULL, NULL, NULL, {0, 3} <unfinished ...>
[pid  1937] <... sched_yield resumed> ) = 0
[pid  1937] futex(0xd35670, FUTEX_WAKE, 1) = 0
[pid  1942] <... select resumed> )      = 0 (Timeout)
[pid  1937] select(0, NULL, NULL, NULL, {0, 20}) = 0 (Timeout)
[pid  1942] sched_yield( <unfinished ...>
[pid  1937] select(0, NULL, NULL, NULL, {0, 20} <unfinished ...>
[pid  1942] <... sched_yield resumed> ) = 0
[pid  1942] futex(0xc42017b798, FUTEX_WAIT, 2, NULL <unfinished ...>
[pid  1937] <... select resumed> )      = 0 (Timeout)
[pid  1937] select(0, NULL, NULL, NULL, {0, 20} <unfinished ...>
[pid  4662] futex(0xc42017b798, FUTEX_WAKE, 1) = 1
[pid  1942] <... futex resumed> )       = 0
[pid  1937] <... select resumed> )      = 0 (Timeout)
[pid  1942] futex(0xc42017b798, FUTEX_WAKE, 1 <unfinished ...>
[pid  1937] select(0, NULL, NULL, NULL, {0, 20} <unfinished ...>
[pid  1942] <... futex resumed> )       = 0
[pid  1942] sched_yield()               = 0
[pid  1937] <... select resumed> )      = 0 (Timeout)
[pid  1942] futex(0xc420368538, FUTEX_WAIT, 2, NULL <unfinished ...>
[pid  1937] select(0, NULL, NULL, NULL, {0, 20} <unfinished ...>
[pid  4662] futex(0xc420368538, FUTEX_WAKE, 1 <unfinished ...>
[pid  1937] <... select resumed> )      = 0 (Timeout)
[pid  1937] select(0, NULL, NULL, NULL, {0, 20} <unfinished ...>
[pid  4662] <... futex resumed> )       = 1
[pid  1942] <... futex resumed> )       = 0
[pid  1942] futex(0xc420368538, FUTEX_WAKE, 1 <unfinished ...>
[pid  1937] <... select resumed> )      = 0 (Timeout)
[pid  1942] <... futex resumed> )       = 0
[pid  1937] select(0, NULL, NULL, NULL, {0, 20} <unfinished ...>
[pid  1942] read(27, 0xc420237400, 1024) = -1 EAGAIN (Resource temporarily unavailable)
[pid  1937] <... select resumed> )      = 0 (Timeout)
[pid  1937] select(0, NULL, NULL, NULL, {0, 20} <unfinished ...>
[pid  4662] epoll_wait(4,  <unfinished ...>
[pid  1937] <... select resumed> )      = 0 (Timeout)
[pid  1937] select(0, NULL, NULL, NULL, {0, 20} <unfinished ...>
[pid  4662] <... epoll_wait resumed> [], 128, 0) = 0
[pid  1937] <... select resumed> )      = 0 (Timeout)
[pid  1937] select(0, NULL, NULL, NULL, {0, 20} <unfinished ...>
[pid  1942] openat(AT_FDCWD, "/var/www/gnaclan/web", O_RDONLY|O_CLOEXEC <unfinished ...>
[pid  1937] <... select resumed> )      = 0 (Timeout)
[pid  1942] <... openat resumed> )      = 23
[pid  1937] select(0, NULL, NULL, NULL, {0, 20} <unfinished ...>
[pid  1942] fstat(23, {st_mode=S_IFDIR|0755, st_size=4096, ...}) = 0
[pid  1937] <... select resumed> )      = 0 (Timeout)
[pid  1942] close(23 <unfinished ...>
[pid  1937] select(0, NULL, NULL, NULL, {0, 20} <unfinished ...>
[pid  1942] <... close resumed> )       = 0
[pid  1942] openat(AT_FDCWD, "/var/www/gnaclan/web/index.php", O_RDONLY|O_CLOEXEC <unfinished ...>
[pid  1937] <... select resumed> )      = 0 (Timeout)
[pid  1942] <... openat resumed> )      = 23
[pid  1937] select(0, NULL, NULL, NULL, {0, 20} <unfinished ...>
[pid  1942] close(23 <unfinished ...>
[pid  1937] <... select resumed> )      = 0 (Timeout)
[pid  1942] <... close resumed> )       = 0
[pid  1937] select(0, NULL, NULL, NULL, {0, 20} <unfinished ...>
[pid  1942] stat("/var/www/gnaclan/web/index.php", {st_mode=S_IFREG|0644, st_size=2097, ...}) = 0
[pid  1937] <... select resumed> )      = 0 (Timeout)
[pid  1937] select(0, NULL, NULL, NULL, {0, 20} <unfinished ...>
[pid  1942] write(15, "\1\1\0\1\0\10\0\0\0\1\1\0\0\0\0\0", 16 <unfinished ...>
[pid  1937] <... select resumed> )      = 0 (Timeout)
[pid  1942] <... write resumed> )       = 16
[pid  1937] select(0, NULL, NULL, NULL, {0, 20} <unfinished ...>
[pid  1942] write(15, "\1\4\0\1\5)\7\0\r\24DOCUMENT_ROOT/var/www/"..., 1336 <unfinished ...>
[pid  1937] <... select resumed> )      = 0 (Timeout)
[pid  1942] <... write resumed> )       = 1336
[pid  1937] select(0, NULL, NULL, NULL, {0, 20} <unfinished ...>
[pid  1942] write(15, "\1\4\0\1\0\0\0\0", 8) = 8
[pid  1937] <... select resumed> )      = 0 (Timeout)
[pid  1942] write(15, "\1\5\0\1\0\0\0\0", 8 <unfinished ...>
[pid  1937] select(0, NULL, NULL, NULL, {0, 20} <unfinished ...>
[pid  1942] <... write resumed> )       = 8
[pid  1942] read(15,  <unfinished ...>
[pid  1937] <... select resumed> )      = 0 (Timeout)
[pid  1942] <... read resumed> "\t// Don'", 8) = 8
[pid  1937] select(0, NULL, NULL, NULL, {0, 20} <unfinished ...>
[pid  1942] read(15, "t consum", 8)     = 8
[pid  1937] <... select resumed> )      = 0 (Timeout)
[pid  1937] select(0, NULL, NULL, NULL, {0, 20} <unfinished ...>
[pid  1942] write(19, "08/Feb/2017:00:06:52 +0100 [ERRO"..., 70 <unfinished ...>
[pid  4662] write(27, "\27\3\3\0)\0\0\0\0\0\0\1\344\237\301+\272\206\234\313\367\37V\365\231$v\212\34\366\26v"..., 46 <unfinished ...>
[pid  1942] <... write resumed> )       = 70
[pid  1937] <... select resumed> )      = 0 (Timeout)
[pid  1937] select(0, NULL, NULL, NULL, {0, 20} <unfinished ...>
[pid  4662] <... write resumed> )       = 46
[pid  1937] <... select resumed> )      = 0 (Timeout)
[pid  1937] futex(0xc4200ee510, FUTEX_WAKE, 1 <unfinished ...>
[pid  1943] <... futex resumed> )       = 0
[pid  1937] <... futex resumed> )       = 1
[pid  1937] select(0, NULL, NULL, NULL, {0, 20} <unfinished ...>
[pid  1943] epoll_wait(4, [], 128, 0)   = 0
[pid  1937] <... select resumed> )      = 0 (Timeout)
[pid  1943] epoll_wait(4,  <unfinished ...>
[pid  1937] select(0, NULL, NULL, NULL, {0, 20} <unfinished ...>
[pid  4662] futex(0xc4200ef910, FUTEX_WAIT, 0, NULL <unfinished ...>
[pid  1937] <... select resumed> )      = 0 (Timeout)
[pid  1942] write(16, "77.23.166.229 - [08/Feb/2017:00:"..., 69 <unfinished ...>
[pid  1937] select(0, NULL, NULL, NULL, {0, 20} <unfinished ...>
[pid  1942] <... write resumed> )       = 69
[pid  4662] <... futex resumed> )       = -1 EAGAIN (Resource temporarily unavailable)
[pid  1942] futex(0xc4200ef910, FUTEX_WAKE, 1 <unfinished ...>
[pid  1937] <... select resumed> )      = 0 (Timeout)
[pid  1942] <... futex resumed> )       = 0
[pid  1937] select(0, NULL, NULL, NULL, {0, 20} <unfinished ...>
[pid  4662] futex(0xc4200ef910, FUTEX_WAIT, 0, NULL <unfinished ...>
[pid  1942] futex(0xc4200ef910, FUTEX_WAKE, 1 <unfinished ...>
[pid  1937] <... select resumed> )      = 0 (Timeout)
[pid  1942] <... futex resumed> )       = 0
[pid  1937] select(0, NULL, NULL, NULL, {0, 20} <unfinished ...>
[pid  4662] <... futex resumed> )       = -1 EAGAIN (Resource temporarily unavailable)
[pid  1942] write(27, "\27\3\3\0@\0\0\0\0\0\0\1\345\230\226\246\336\254\201g\37\310\274\2312Scf\325s\271\344"..., 69 <unfinished ...>
[pid  1937] <... select resumed> )      = 0 (Timeout)
[pid  1942] <... write resumed> )       = 69
[pid  1937] select(0, NULL, NULL, NULL, {0, 20} <unfinished ...>
[pid  4662] futex(0xc4203dc910, FUTEX_WAKE, 1 <unfinished ...>
[pid  1942] futex(0xc4203dc910, FUTEX_WAIT, 0, NULL <unfinished ...>
[pid  1937] <... select resumed> )      = 0 (Timeout)
[pid  1942] <... futex resumed> )       = -1 EAGAIN (Resource temporarily unavailable)
[pid  1937] select(0, NULL, NULL, NULL, {0, 20} <unfinished ...>
[pid  1942] select(0, NULL, NULL, NULL, {0, 3} <unfinished ...>
[pid  4662] <... futex resumed> )       = 0
[pid  1942] <... select resumed> )      = 0 (Timeout)
[pid  1937] <... select resumed> )      = 0 (Timeout)
[pid  1942] futex(0xc4203dc910, FUTEX_WAIT, 0, NULL <unfinished ...>
[pid  1937] select(0, NULL, NULL, NULL, {0, 20} <unfinished ...>
[pid  4662] futex(0xc4203dc910, FUTEX_WAKE, 1 <unfinished ...>
[pid  1937] <... select resumed> )      = 0 (Timeout)
[pid  1937] select(0, NULL, NULL, NULL, {0, 20} <unfinished ...>
[pid  4662] <... futex resumed> )       = 1
[pid  1942] <... futex resumed> )       = 0
[pid  1937] <... select resumed> )      = 0 (Timeout)
[pid  1942] select(0, NULL, NULL, NULL, {0, 3} <unfinished ...>
[pid  1937] select(0, NULL, NULL, NULL, {0, 20} <unfinished ...>
[pid  1942] <... select resumed> )      = 0 (Timeout)
[pid  4662] write(27, "\27\3\3\0I\0\0\0\0\0\0\1\346\362\365\355\362&\320<\31H\276\202\301\262x\251\325Vt\257"..., 78 <unfinished ...>
[pid  1942] futex(0xc4203dc910, FUTEX_WAIT, 0, NULL <unfinished ...>
[pid  4662] <... write resumed> )       = 78
[pid  1937] <... select resumed> )      = 0 (Timeout)
[pid  4662] futex(0xc4203dc910, FUTEX_WAKE, 1 <unfinished ...>
[pid  1937] select(0, NULL, NULL, NULL, {0, 20} <unfinished ...>
[pid  4662] <... futex resumed> )       = 1
[pid  1942] <... futex resumed> )       = 0
[pid  4662] futex(0xc4200ef910, FUTEX_WAIT, 0, NULL <unfinished ...>
[pid  1942] futex(0xc4203dc910, FUTEX_WAIT, 0, NULL <unfinished ...>
[pid  1937] <... select resumed> )      = 0 (Timeout)
[pid  1937] futex(0xd35738, FUTEX_WAIT, 0, {60, 0}^Cstrace: Process 1935 detached
strace: Process 1937 detached
 <detached ...>
strace: Process 1938 detached
strace: Process 1939 detached
strace: Process 1940 detached
strace: Process 1941 detached
strace: Process 1942 detached
strace: Process 1943 detached
strace: Process 3954 detached
strace: Process 4659 detached
strace: Process 4660 detached
strace: Process 4661 detached
strace: Process 4662 detached
strace: Process 4663 detached
strace: Process 4664 detached
strace: Process 4665 detached

I’m convinced there’s a bug in the fastcgi middleware. I need someone who is dedicated to look into it, as it may not be obvious. I would be surprised if this was not related to https://github.com/mholt/caddy/issues/1204.

Also, upgrade Caddy.

Want to take a stab at this?

I will have a look at the ticket and update ASAP.

Thanks for the fast response!

I had similar problems with 0.9.2 and PHP fast-cgi you need to upgrade to 0.9.3 or higher.

@davidak Can you confirm that upgrading solved the issue for you?

This topic was automatically closed 90 days after the last reply. New replies are no longer allowed.

@davidak I’m still worried there may be a bug in the FastCGI middleware. Did you ever upgrade and see if that fixed the problem for you?