Proxy protocol error in apache logs of my virtual host

[vilasmankala]

I have a two virtual hosts on three linux servers behind an ELB. I have enabled proxy protocol for my ELB so that the requests for ssl are terminated on instance rather than on ELB. I am seeing following errors very continuously in my one of the virtual host logs

Error log:

[Thu Oct 19 14:57:07.126415 2017] [proxy_protocol:error] [pid 2992] [client 127.0.0.1:47348] ProxyProtocol: no valid header found
[Thu Oct 19 14:57:07.471596 2017] [proxy_protocol:error] [pid 3076] [client 127.0.0.1:47388] ProxyProtocol: no valid header found
[Thu Oct 19 14:57:07.785776 2017] [proxy_protocol:error] [pid 3076] [client 127.0.0.1:47428] ProxyProtocol: no valid header found
[Thu Oct 19 14:57:07.909984 2017] [proxy_protocol:error] [pid 2528] [client 127.0.0.1:47450] ProxyProtocol: no valid header found
[Thu Oct 19 14:57:08.384383 2017] [proxy_protocol:error] [pid 2612] [client 127.0.0.1:47496] ProxyProtocol: no valid header found

Access logs:

127.0.0.1 - - [19/Oct/2017:14:57:45 +0000] "GET /admin/index.php HTTP/1.1" 302 - "-" "-"
127.0.0.1 - - [19/Oct/2017:14:57:45 +0000] "GET /? HTTP/1.1" 302 - "-" "-"
127.0.0.1 - - [19/Oct/2017:14:57:45 +0000] "GET /admin/index.php HTTP/1.1" 302 - "-" "-"
127.0.0.1 - - [19/Oct/2017:14:57:45 +0000] "GET /? HTTP/1.1" 302 - "-" "-"
127.0.0.1 - - [19/Oct/2017:14:57:45 +0000] "GET /admin/index.php HTTP/1.1" 302 - "-" "-"
127.0.0.1 - - [19/Oct/2017:14:57:46 +0000] "GET /? HTTP/1.1" 302 - "-" "-"
127.0.0.1 - - [19/Oct/2017:14:57:46 +0000] "GET /admin/index.php HTTP/1.1" 302 - "-" "-"
127.0.0.1 - - [19/Oct/2017:14:57:46 +0000] "GET /? HTTP/1.1" 302 - "-" "-"
127.0.0.1 - - [19/Oct/2017:14:57:46 +0000] "GET /admin/index.php HTTP/1.1" 302 - "-" "-"

Could you please suggest on how to eliminate these errors. These errors started very recently and before I didnt find any of these errors. I tried to create the replica of my existing setup and from then these errors started. I even deleted the replica setup and also checked with AWS support team.
My QA environment is running fine with any errors.

I refered to below link but didnt find it helpful to resolve my case.
#3

Thank you,

[roadrunner2]

I don't have enough information about your exact config or setup to tell for sure, but it looks like you have something running on the same machine that is hitting your webserver (some type of monitoring, maybe?) since the ip-address for all accesses above is localhost; and assuming you set up the two virtual hosts such that one has proxy-protocol enabled and one not, then that thing appears to be hitting both your virtual hosts, instead of just the one with proxy-protocol disabled. The fact that you don't see this on the original setup, but only on the new, also indicates it is something to do with the new machines rather than your configuration. So I'd see what else is running on those machines, and what cron-jobs there are, and see if anything sticks out.

[vilasmankala]

I have only two cronjobs running on my machine which moves the access and error logs to S3. This is my prod server with Apache 2.4 and php5.6 running on it. We have installed the proxy protocol module for Apache HTTPD from below source
https://github.com/roadrunner2/mod-proxy-protocol

We have enabled the proxy protocol at ELB level so that the ssl connection terminates at instance rather than at ELB. The "ProxyProtocol: no valid header found" errors were started to appear from 11th-Oct 2017 and we are yet to figure the root cause. These error logs are flowing continuously since then and I see the below part of code is triggering the proxy protocol error

mod_proxy_protocol.c
------------------------

/* Determine if this is a v1 or v2 header.
 */
static int pp_determine_version(conn_rec c, const char ptr)
{
    proxy_header hdr = (proxy_header ) ptr;

    / assert len >= 14 /

    if (memcmp(&hdr->v2, v2sig, sizeof(v2sig)) == 0 &&
        (hdr->v2.ver_cmd & 0xF0) == 0x20) {
        return 2;
    }
    else if (memcmp(hdr->v1.line, "PROXY ", 6) == 0) {
        return 1;
    }
    else {
       ap_log_cerror(APLOG_MARK, APLOG_ERR, 0, c, 
                     "ProxyProtocol: no valid header found");
       return -1;
    }
}

There is nothing changed on the server for long time. Could you please let me know how these errors could be caused or some kind of source which cause this errors. Any possible solution for this is much appreciated.

My httpd.conf file:

ServerRoot "/etc/httpd"

#
#Listen 12.34.56.78:80
Listen 80

#
# Example:
# LoadModule foo_module modules/mod_foo.so
#
Include conf.modules.d/*.conf

#
# ServerAdmin: Your address, where problems with the server should be
# e-mailed.  This address appears on some server-generated pages, such
# as error documents.  e.g. [email protected]
#
ServerAdmin root@localhost

#
# ServerName gives the name and port that the server uses to identify itself.
# This can often be determined automatically, but we recommend you specify
# it explicitly to prevent problems during startup.
#
# If your host doesn't have a registered DNS name, enter its IP address here.
#
#ServerName www.example.com:80

#
# Deny access to the entirety of your server's filesystem. You must
# explicitly permit access to web content directories in other
# <Directory> blocks below.
#
<Directory />
    AllowOverride none
    Require all denied
</Directory>

#
# DocumentRoot: The directory out of which you will serve your
# documents. By default, all requests are taken from this directory, but
# symbolic links and aliases may be used to point to other locations.
#
DocumentRoot "/var/www/html"

#
# Relax access to content within /var/www.
#
<Directory "/var/www">
    AllowOverride None
    # Allow open access:
    Require all granted
</Directory>

# Further relax access to the default document root:
<Directory "/var/www/html">
    Options Indexes FollowSymLinks
    AllowOverride None
    Require all granted
</Directory>
#
# DirectoryIndex: sets the file that Apache will serve if a directory
# is requested.
#
<IfModule dir_module>
    DirectoryIndex index.html
</IfModule>

#
# The following lines prevent .htaccess and .htpasswd files from being
# viewed by Web clients.
#
<Files ".ht*">
    Require all denied
</Files>

#ErrorLog "logs/error_log"
ErrorLog "|/usr/sbin/rotatelogs -l /var/log/httpd/error_log-%Y%m%d-i-0c452f7df2da0d7ba 86400"
#
# LogLevel: Control the number of messages logged to the error_log.
# Possible values include: debug, info, notice, warn, error, crit,
# alert, emerg.
#
LogLevel warn

<IfModule log_config_module>
    LogFormat "%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\"" combined
    LogFormat "%h %l %u %t \"%r\" %>s %b" common

    <IfModule logio_module>
      # You need to enable mod_logio.c to use %I and %O
      LogFormat "%h %l %u %t \"%r\" %>s %b \"%{Referer}i\" \"%{User-Agent}i\" %I %O" combinedio
    </IfModule>

    #CustomLog "logs/access_log" common
    #CustomLog "logs/access_log" combined
    CustomLog "|/usr/sbin/rotatelogs -l /var/log/httpd/access_log-%Y%m%d-i-0c452f7df2da0d7ba 86400" combined
</IfModule>

<IfModule alias_module>
 
    ScriptAlias /cgi-bin/ "/var/www/cgi-bin/"

</IfModule>

<Directory "/var/www/cgi-bin">
    AllowOverride None
    Options None
    Require all granted
</Directory>

<IfModule mime_module>
    TypesConfig /etc/mime.types
    #AddType application/x-gzip .tgz
    #
    # AddEncoding allows you to have certain browsers uncompress
    # information on the fly. Note: Not all browsers support this.
    #
    #AddEncoding x-compress .Z
    #AddEncoding x-gzip .gz .tgz
    AddType application/x-compress .Z
    AddType application/x-gzip .gz .tgz
    #
    #AddHandler cgi-script .cgi

    # For type maps (negotiated resources):
    #AddHandler type-map var

    #
    # Filters allow you to process content before it is sent to the client.
    #
    # To parse .shtml files for server-side includes (SSI):
    # (You will also need to add "Includes" to the "Options" directive.)
    #
    AddType text/html .shtml
    AddOutputFilter INCLUDES .shtml
</IfModule>
#
AddDefaultCharset UTF-8

<IfModule mime_magic_module>
    MIMEMagicFile conf/magic
</IfModule>

# Customizable error responses come in three flavors:
# 1) plain text 2) local redirects 3) external redirects
#
# Some examples:
#ErrorDocument 500 "The server made a boo boo."
#ErrorDocument 404 /missing.html
#ErrorDocument 404 "/cgi-bin/missing_handler.pl"
#ErrorDocument 402 http://www.example.com/subscription_info.html

#EnableMMAP off
EnableSendfile on

# Supplemental configuration
#
# Load config files in the "/etc/httpd/conf.d" directory, if any.
IncludeOptional conf.d/*.conf

#### AWS Settings ####

# Disable ETag headers
FileETag none

# Hide Apache and PHP info
Header unset Server
Header unset X-Powered-By

# Don't expose server versions
ServerSignature Off
ServerTokens Prod

# Enable server-status for internal IP
<Location /server-status>
   SetHandler server-status
   Order Deny,Allow
   Deny from all
   Allow from 127.0.0.1
</Location>

# KeepAlive: Whether or not to allow persistent connections (more than
# one request per connection). Set to "Off" to deactivate.
KeepAlive On

SetEnv ENVIRONMENT production

#### End of AWS Settings ####

[roadrunner2]

The logs are definitely indicating the problematic connections are coming from the same machine - what other requests/accesses are you seeing from localhost? Maybe that will give a clue. You can also verify that it's something on the local machine by running something like tshark/wireshark and capturing/monitoring the traffic on the loopback interface - maybe by seeing the full http request being sent (inluding things like the user-agent header) that will also give clue.

[vilasmankala]

I have took the tcpdump and also shared the same with AWS support team. Below is the header appended by the ELB to the requests
PROXY TCP4 52.201.58.209 10.1.6.70 24258 443

AWS team also confirmed that everythings looks normal at ELB level and the proxy header is also as expected.

The only cronjobs running on my machines are the two crons that move my error and access logs to S3. I see that only redirection requests are generated by 127.0.0.1 ip.

Access logs:

127.0.0.1 - - [23/Oct/2017:17:30:33 +0000] "GET /? HTTP/1.1" 302 - "-" "-"
127.0.0.1 - - [23/Oct/2017:17:30:33 +0000] "GET /admin/index.php HTTP/1.1" 302 - "-" "-"
127.0.0.1 - - [23/Oct/2017:17:30:33 +0000] "GET /? HTTP/1.1" 302 - "-" "-"
127.0.0.1 - - [23/Oct/2017:17:30:33 +0000] "GET /admin/index.php HTTP/1.1" 302 - "-" "-"
127.0.0.1 - - [23/Oct/2017:17:30:33 +0000] "GET /? HTTP/1.1" 302 - "-" "-"
127.0.0.1 - - [23/Oct/2017:17:30:33 +0000] "GET /? HTTP/1.1" 302 - "-" "-"
127.0.0.1 - - [23/Oct/2017:17:30:33 +0000] "GET /admin/index.php HTTP/1.1" 302 - "-" "-"
127.0.0.1 - - [23/Oct/2017:17:30:33 +0000] "GET /? HTTP/1.1" 302 - "-" "-"
127.0.0.1 - - [23/Oct/2017:17:30:33 +0000] "GET /admin/index.php HTTP/1.1" 302 - "-" "-"
127.0.0.1 - - [23/Oct/2017:17:30:33 +0000] "GET /? HTTP/1.1" 302 - "-" "-"
127.0.0.1 - - [23/Oct/2017:17:30:33 +0000] "GET /admin/index.php HTTP/1.1" 302 - "-" "-"
127.0.0.1 - - [23/Oct/2017:17:30:33 +0000] "GET /? HTTP/1.1" 302 - "-" "-"
127.0.0.1 - - [23/Oct/2017:17:30:33 +0000] "GET /admin/index.php HTTP/1.1" 302 - "-" "-"
127.0.0.1 - - [23/Oct/2017:17:30:33 +0000] "GET /? HTTP/1.1" 302 - "-" "-"

So are these redirection requests causing the proxy protocol errors. Or it could be someother thing that I need to check.

[bcc]

I've spent some time digging into this as we've been seeing the same issue and it's been a bit painful to reproduce. It turns out that it's caused by apache itself trying to send an "OPTIONS *" request as part of the process of shutting down an idle process (at least with mpm_prefork and mpm_itk). If you're seeing it a lot, you probably want to consider adjusting the SpareServers configuration options to be less aggressive at cleaning up spare children. It happens after the child has finished handling any client requests, so the log entries are annoying but harmless.

[bcc]

And it appears that mod_remoteip has fixed that by simply removing the warning message:

ap_log_cerror(APLOG_MARK, APLOG_ERR, 0, c, 
    "ProxyProtocol: no valid header found");

[roadrunner2]

@bcc Thanks for chasing this down! Though I think the approach apparently taken by mod_remoteip of just removing the error message wholesale is wrong (but looking at the history it may have been somewhat unintentional). However, I also don't have the bandwidth right now to figure out how to properly detect these internal OPTIONS requests, so for now I guess folks should just comment out/remove the error if it's causing them grief.