404 for one file, but not for others

[ChristianNally]

phpinfo.php is giving me a 404 result, where another file is accessed without a problem.

ls -l test.html phpinfo.php
-rw-r--r-- 1 christiannally wheel 18 27 Feb 14:39 phpinfo.php
-rw-r--r-- 1 christiannally wheel 26 27 Feb 14:40 test.html

I can edit test.html and the changes work right away. Accessing phpinfo.php returns a 404.

Codebase

mounted codebase

Host OS

macOS Sierra

Docker info output

Containers: 8
 Running: 8
 Paused: 0
 Stopped: 0
Images: 8
Server Version: 17.12.0-ce
Storage Driver: overlay2
 Backing Filesystem: extfs
 Supports d_type: true
 Native Overlay Diff: true
Logging Driver: json-file
Cgroup Driver: cgroupfs
Plugins:
 Volume: local
 Network: bridge host ipvlan macvlan null overlay
 Log: awslogs fluentd gcplogs gelf journald json-file logentries splunk syslog
Swarm: inactive
Runtimes: runc
Default Runtime: runc
Init Binary: docker-init
containerd version: 89623f28b87a6004d4b785663257362d1658a729
runc version: b2567b37d7b75eb4cf325b77297b140ea686ce8f
init version: 949e6fa
Security Options:
 seccomp
  Profile: default
Kernel Version: 4.9.60-linuxkit-aufs
Operating System: Docker for Mac
OSType: linux
Architecture: x86_64
CPUs: 2
Total Memory: 3.855GiB
Name: linuxkit-025000000001
ID: SFX6:7VI3:P3KC:TDPE:54AQ:R2OX:DMDB:MGQR:BNVU:XMZJ:5IAG:MAQN
Docker Root Dir: /var/lib/docker
Debug Mode (client): false
Debug Mode (server): true
 File Descriptors: 96
 Goroutines: 136
 System Time: 2018-02-27T23:44:29.744893581Z
 EventsListeners: 4
HTTP Proxy: docker.for.mac.http.internal:3128
HTTPS Proxy: docker.for.mac.http.internal:3129
Registry: https://index.docker.io/v1/
Labels:
Experimental: true
Insecure Registries:
 127.0.0.0/8
Live Restore Enabled: false

Docker compose file

version: "2"

services:
  mariadb:
    image: wodby/mariadb:10.2-3.0.2
    environment:
      MYSQL_ROOT_PASSWORD: password
      MYSQL_DATABASE: drupal
      MYSQL_USER: drupal
      MYSQL_PASSWORD: drupal
    volumes:
      - ./mariadb-init:/docker-entrypoint-initdb.d # Place init .sql file(s) here.
#      - /path/to/mariadb/data/on/host:/var/lib/mysql # I want to manage volumes manually.

  php:
    image: wodby/drupal-php:5.6-dev-3.3.1
    environment:
      PHP_SENDMAIL_PATH: /usr/sbin/sendmail -t -i -S mailhog:1025
      PHP_FPM_CLEAR_ENV: "no"
      DB_HOST: mariadb
      DB_USER: drupal
      DB_PASSWORD: drupal
      DB_NAME: drupal
      DB_DRIVER: mysql
#      PHP_XDEBUG: 1
#      PHP_XDEBUG_DEFAULT_ENABLE: 1
#      PHP_XDEBUG_REMOTE_CONNECT_BACK: 0
#      PHP_XDEBUG_REMOTE_HOST: "10.254.254.254"
#      PHP_XDEBUG_PROFILER_OUTPUT_DIR: /mnt/files/xdebug/profiler
#      PHP_XDEBUG_TRACE_OUTPUT_DIR: /mnt/files/xdebug/traces
#      PHP_BLACKFIRE: 1
    volumes:
      - .:/var/www/html
## Options for macOS users (https://docker4drupal.readthedocs.io/en/latest/macos)
#      - codebase:/var/www/html:cached # User-guided caching
#      - docker-sync:/var/www/html # Docker-sync
## For Xdebug profiler files
#      - files:/mnt/files

  nginx:
    image: wodby/drupal-nginx:7-1.13-3.0.2
    depends_on:
      - php
    environment:
      NGINX_STATIC_CONTENT_OPEN_FILE_CACHE: "off"
      NGINX_ERROR_LOG_LEVEL: debug
      NGINX_BACKEND_HOST: php
      NGINX_SERVER_ROOT: /var/www/html
#      NGINX_DRUPAL_FILE_PROXY_URL: http://example.com
    volumes:
      - .:/var/www/html
# Options for macOS users (https://docker4drupal.readthedocs.io/en/latest/macos)
#      - codebase:/var/www/html:cached # User-guided caching
#      - docker-sync:/var/www/html # Docker-sync
    labels:
      - 'traefik.backend=nginx'
      - 'traefik.port=80'
      - 'traefik.frontend.rule=Host:drupal.docker.localhost'

#  adminer:
#    image: wodby/adminer:4.3-1.1.0
#    environment:
#      ADMINER_SALT: adminer-salt
#    labels:
#      - 'traefik.backend=adminer'
#      - 'traefik.port=9000'
#      - 'traefik.frontend.rule=Host:adminer.drupal.docker.localhost'

  pma:
    image: phpmyadmin/phpmyadmin
    environment:
      PMA_HOST: mariadb
      PMA_USER: drupal
      PMA_PASSWORD: drupal
      PHP_UPLOAD_MAX_FILESIZE: 1G
      PHP_MAX_INPUT_VARS: 1G
    labels:
      - 'traefik.backend=pma'
      - 'traefik.port=80'
      - 'traefik.frontend.rule=Host:pma.drupal.docker.localhost'

  solr:
    image: wodby/drupal-solr:7-5.4-2.3.0
    environment:
      SOLR_HEAP: 1024m
    labels:
      - 'traefik.backend=solr'
      - 'traefik.port=8983'
      - 'traefik.frontend.rule=Host:solr.drupal.docker.localhost'

  mailhog:
    image: mailhog/mailhog
    labels:
      - 'traefik.backend=mailhog'
      - 'traefik.port=8025'
      - 'traefik.frontend.rule=Host:mailhog.drupal.docker.localhost'

  portainer:
    image: portainer/portainer
    command: --no-auth -H unix:///var/run/docker.sock
    volumes:
      - /var/run/docker.sock:/var/run/docker.sock
    labels:
      - 'traefik.backend=portainer'
      - 'traefik.port=9000'
      - 'traefik.frontend.rule=Host:portainer.drupal.docker.localhost'

  traefik:
    image: traefik
    command: -c /dev/null --web --docker --logLevel=INFO
    ports:
      - '8000:80'
#      - '8080:8080' # Dashboard
    volumes:
      - /var/run/docker.sock:/var/run/docker.sock

volumes:
  codebase:
## Docker-sync for macOS users
#  docker-sync:
#    external: true
## For Xdebug profiler
#  files:

Logs output

nginx_1      | 172.18.0.4 - - [27/Feb/2018:23:46:46 +0000] "GET /phpinfo.php HTTP/1.1" 404 193 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/64.0.3282.167 Safari/537.36"
nginx_1      | 172.18.0.4 - - [27/Feb/2018:23:46:46 +0000] "GET /favicon.ico HTTP/1.1" 200 43 "http://drupal.docker.localhost:8000/phpinfo.php" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/64.0.3282.167 Safari/537.36"

php_1        | 172.18.0.9 -  27/Feb/2018:22:31:47 +0000 "GET /index.php" 500
php_1        | 172.18.0.9 -  27/Feb/2018:22:37:38 +0000 "GET /index.php" 500
php_1        | [27-Feb-2018 22:41:48] NOTICE: Terminating ...
php_1        | [27-Feb-2018 22:41:48] NOTICE: exiting, bye-bye!
php_1        | [27-Feb-2018 23:19:30] NOTICE: fpm is running, pid 1
php_1        | [27-Feb-2018 23:19:30] NOTICE: ready to handle connections

[szeidler]

For security reasons the drupal-nginx image returns 404, for all not whitelisted PHP files. You can see it in the template https://github.com/wodby/drupal-nginx/blob/master/templates/d7-vhost.conf.tpl#L228-L230.

If you like to see the phpinfo, you can always log in into your Drupal installation as an admin and open admin/reports/status/php

[ChristianNally]

Thanks @szeidler

While I have you on the line, I've not yet been able to get my own Drupal code working. I could see php info via 'php -i' in that container, but setting the error log location etc. in settings.php hasn't enabled me to get full 500 error text.

I am getting some log entries that show the occurance of the 500 error, but not the actual error message itself.

php_1        | 172.18.0.9 -  27/Feb/2018:19:52:10 +0000 "GET /index.php" 500
php_1        | 172.18.0.9 -  27/Feb/2018:20:08:42 +0000 "GET /index.php" 500
php_1        | 172.18.0.9 -  27/Feb/2018:22:25:29 +0000 "GET /index.php" 500
php_1        | 172.18.0.9 -  27/Feb/2018:22:31:47 +0000 "GET /index.php" 500

nginx_1      | 172.18.0.4 - - [28/Feb/2018:17:20:18 +0000] "GET / HTTP/1.1" 499 0 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/64.0.3282.167 Safari/537.36"
nginx_1      | 2018/02/28 17:20:18 [info] 24#24: *3 epoll_wait() reported that client prematurely closed connection, so upstream connection is closed too while sending request to upstream, client: 172.18.0.4, server: drupal, request: "GET / HTTP/1.1", upstream: "fastcgi://172.18.0.8:9000", host: "drupal.docker.localhost:8000"
nginx_1      | 172.18.0.4 - - [28/Feb/2018:17:20:59 +0000] "GET / HTTP/1.1" 500 5 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/64.0.3282.167 Safari/537.36"

I may be having trouble because I'm not used to nginx administration. Do you have a "tip jar" I can contribute too?

Thanks for the work on this excellent project!

[szeidler]

When you set $conf['error_level'] = 2; in your settings.php, Drupal should present you errors and exceptions on the screen.
As I'm "only" a Docker4Drupal user and no maintainer I cannot explain why they are not streamed to the logs :)

[csandanov]

I cannot explain why they are not streamed to the logs :)

Don't you see errors in stdout after changing the error_level?

[robertoperuzzo]

I added $conf['error_level'] = 2; in my settings.php, but I don't see any php errors in stdout yet (running docker-compose logs php).

[csandanov]

AFAIK, Drupal (at least Drupal 7) uses its own error handlers and have two error log destinations: dblog and syslog. There's no syslog daemon in php container because, you know, containers, we have one process per container. You can check it by commenting the following lines in _drupal_bootstrap_configuration():

  set_error_handler('_drupal_error_handler');
  set_exception_handler('_drupal_exception_handler');

Solutions:

1. implement your own _watchdog hook and stream errors to the default error_log (which is container's output)
2. Use monolog module with udp syslog plugin and stream all errors to rsyslog container as described at https://wodby.com/stacks/drupal/docs/containers/rsyslog/, this way you'll see all errors in rsyslog container output

[csandanov]

Ok, turns out we had a problem here after all, log_errors was disabled. It's obviously a misconfiguration. Although the written above is still correct, drupal uses its own handler

[csandanov]

Fixed in 5.0.4