ISPConfig httpd access log symlinks and log rotation not working completely correctly

Hello!

I have several similarly-configured ISPConfig servers, and httpd log rotation is working correctly on all of them except one. I'm not sure what broke it (or if it ever worked correctly).

Basically, I noticed that nginx's access logs were empty, for every single vhost on the server. More specifically, "access.log" was zero-bytes in every case, and the rotated/gzipped logs were all 40 bytes (a zero-byte file wrapped in a minimally-sized gzip archive).

Sometimes, "re-syncing" the server fixes certain configuration issues, so I gave it a try, and it did change the behavior, but it's still not entirely correct.

After the re-sync, access entries are being written, but they are being written to the wrong file. Instead of being written to "access.log", they are being written to yesterday's rotated file, "20170103-access.log", per the example below.

The "ls" output for one such vhost's "log" directory looks like this:

Code:

ls -lah .
total 484K
drwxr-xr-x 2 root  root 4.0K Jan  4 00:01 .
drwxr-xr-x 9 root  root 4.0K Sep 22 20:28 ..
-rw-r--r-- 1 root  root  40 Dec  8 00:01 20161206-access.log.gz
-rw-r--r-- 1 root  root  40 Dec  9 00:01 20161207-access.log.gz
-rw-r--r-- 1 root  root  40 Dec 10 00:01 20161208-access.log.gz
-rw-r--r-- 1 root  root  40 Dec 11 00:01 20161209-access.log.gz
-rw-r--r-- 1 root  root  40 Dec 12 00:01 20161210-access.log.gz
-rw-r--r-- 1 root  root  40 Dec 13 00:01 20161211-access.log.gz
-rw-r--r-- 1 root  root  40 Dec 14 00:01 20161212-access.log.gz
-rw-r--r-- 1 root  root  40 Dec 15 00:01 20161213-access.log.gz
-rw-r--r-- 1 root  root  40 Dec 16 00:01 20161214-access.log.gz
-rw-r--r-- 1 root  root  40 Dec 17 00:01 20161215-access.log.gz
-rw-r--r-- 1 root  root  40 Dec 18 00:01 20161216-access.log.gz
-rw-r--r-- 1 root  root  40 Dec 19 00:01 20161217-access.log.gz
-rw-r--r-- 1 root  root  40 Dec 20 00:01 20161218-access.log.gz
-rw-r--r-- 1 root  root  40 Dec 21 00:01 20161219-access.log.gz
-rw-r--r-- 1 root  root  40 Dec 22 00:02 20161220-access.log.gz
-rw-r--r-- 1 root  root  40 Dec 23 00:01 20161221-access.log.gz
-rw-r--r-- 1 root  root  40 Dec 24 00:02 20161222-access.log.gz
-rw-r--r-- 1 root  root  40 Dec 25 00:01 20161223-access.log.gz
-rw-r--r-- 1 root  root  40 Dec 26 00:01 20161224-access.log.gz
-rw-r--r-- 1 root  root  40 Dec 27 00:01 20161225-access.log.gz
-rw-r--r-- 1 root  root  40 Dec 28 00:02 20161226-access.log.gz
-rw-r--r-- 1 root  root  40 Dec 29 00:01 20161227-access.log.gz
-rw-r--r-- 1 root  root  40 Dec 30 00:01 20161228-access.log.gz
-rw-r--r-- 1 root  root  40 Dec 31 00:02 20161229-access.log.gz
-rw-r--r-- 1 root  root  40 Jan  1 00:01 20161230-access.log.gz
-rw-r--r-- 1 root  root  40 Jan  2 00:01 20161231-access.log.gz
-rw-r--r-- 1 root  root  12K Jan  3 00:01 20170101-access.log.gz
-rw-r--r-- 1 root  root  40 Jan  4 00:01 20170102-access.log.gz
-rw-r--r-- 1 www-data root 299K Jan  4 10:00 20170103-access.log
-rw-r--r-- 1 www-data root  0 Jan  4 00:00 access.log
-rw-r--r-- 1 www-data root  13K Jan  1 17:54 error.log
-rw-r--r-- 1 root  root  33K Jan  4 00:01 webalizer.conf

How shall I fix this? Do I just need to wait another 24 hours for some scheduled ISPConfig job to run?

For what it's worth, I ran the re-sync yesterday, at about 17:00 local time (it is now 10:25 local time, the following day).

Thanks for any clues!

 

Thank you for taking a look, Till!

I checked it this morning (a full 48 hours later) and the access.log is empty again, as are the log files for the last couple of days.

Here are the log directory contents:

Code:

ls -lah /var/www/example.com/log
total 212K
drwxr-xr-x 2 root  root 4.0K Jan  6 00:01 .
drwxr-xr-x 9 root  root 4.0K Sep 22 20:28 ..
[...]
-rw-r--r-- 1 root  root  40 Dec 30 00:01 20161228-access.log.gz
-rw-r--r-- 1 root  root  40 Dec 31 00:02 20161229-access.log.gz
-rw-r--r-- 1 root  root  40 Jan  1 00:01 20161230-access.log.gz
-rw-r--r-- 1 root  root  40 Jan  2 00:01 20161231-access.log.gz
-rw-r--r-- 1 root  root  12K Jan  3 00:01 20170101-access.log.gz
-rw-r--r-- 1 root  root  40 Jan  4 00:01 20170102-access.log.gz
-rw-r--r-- 1 root  root  36K Jan  5 00:01 20170103-access.log.gz
-rw-r--r-- 1 root  root  40 Jan  6 00:01 20170104-access.log.gz
-rw-r--r-- 1 www-data root  0 Jan  5 00:00 20170105-access.log
-rw-r--r-- 1 www-data root  0 Jan  6 00:00 access.log
-rw-r--r-- 1 www-data root  13K Jan  1 17:54 error.log
-rw-r--r-- 1 root  root  33K Jan  6 00:01 webalizer.conf

We can see that the logs are not empty on Jan 3 and Jan 5. I ran the resync on Jan 3, for what it's worth. I'm not sure why access logging would work on the Jan 3, but not Jan 4, and then work again on Jan 5.

To be clear, there should be access log entries at least every minute on the vhosts in question (there are cron jobs that hit URLs on schedule). Obviously, I have also tested accessing the vhosts manually, in a browser, and the accesses still are not logged.

What else shall I check? Thanks!

 

Yes, the output from these two commands is identical:

Code:

ls -lah /var/log/ispconfig/httpd/domain.tld/

Code:

ls -lah /var/www/domain.tld/log

And yes, there is a bind mount for every vhost on the server in /etc/fstab. They look like this:

Code:

/var/log/ispconfig/httpd/domain.tld /var/www/clients/client1/web1/log  none  bind,nobootwait  0 0

It all looks to be normal/correct to me... :/

 

Thanks again, Till. I appreciate your willingness to help me troubleshoot this.

Yes, I checked all of the items you mentioned before posting about this issue.

It does seem to be a problem with nginx, for the reasons you mentioned. Again, this issue is happening with every vhost on the server.

Here is the complete nginx config for one affected vhost:

Code:

server {
  listen 192.168.1.123:80;

  listen 192.168.1.123:443 ssl;
  ssl_certificate /var/www/clients/client1/web3/ssl/domain.tld.crt;
  ssl_certificate_key /var/www/clients/client1/web3/ssl/domain.tld.key;

  server_name domain.tld ;

  root  /var/www/domain.tld/web/;



  index index.html index.htm index.php index.cgi index.pl index.xhtml;



  error_log /var/log/ispconfig/httpd/domain.tld/error.log;
  access_log /var/log/ispconfig/httpd/domain.tld/access.log combined;

  location ~ /\.(?!well-known/acme-challenge/) {
  deny all;
  access_log off;
  log_not_found off;
  }

  location = /favicon.ico {
  log_not_found off;
  access_log off;
  }

  location = /robots.txt {
  allow all;
  log_not_found off;
  access_log off;
  }

  location /stats/ {

  index index.html index.php;
  auth_basic "Members Only";
  auth_basic_user_file /var/www/clients/client1/web3/web/stats/.htpasswd_stats;
  }

  location ^~ /awstats-icon {
  alias /usr/share/awstats/icon;
  }

  location ~ \.php$ {
  try_files /ca79ec66b625dc6f0b1b8f55b922e7d4.htm @php;
  }

  location @php {
  try_files $uri =404;
  include /etc/nginx/fastcgi_params;
  fastcgi_pass unix:/var/lib/php7.0-fpm/web3.sock;
  fastcgi_index index.php;
  fastcgi_param SCRIPT_FILENAME $document_root$fastcgi_script_name;
  fastcgi_intercept_errors on;
  }







  location ~ /\.well-known/acme-challenge/ {
    root /usr/local/ispconfig/interface/acme/;
    index index.html index.htm;
    try_files $uri =404;
  }



}

It is entirely stock; I don't think I've made a single customization to this vhost. And yet, no access logging.

This is a production server, so I can't easily fiddle-around and, for example, completely purge nginx and reinstall it. I would have to schedule a change order and planned downtime, which would be far less than ideal.

What's also odd is that error logging works just fine. Why would nginx be able to log errors, but not access attempts???

Another interesting fact is that access logging starts to work again if I restart (or maybe even reload) nginx. I am going to test that theory definitively, and see how long it works for. But even still, the symlinks are incorrect (as mentioned in the OP), even when access logging starts working again, after a restart/reload.

I can't find any other instance of this behavior on the Internet... all searches are a dead-end.

 

Yes, I can confirm that access logging starts working again, immediately, if I reload nginx. It's not a resource consumption issue, because the server has 8GB of RAM, 7 of which is available. And the disk is nowhere near full.

Given that this is clearly a problem with nginx, and not ISPConfig (at least given all evidence available at this stage), you are off the hook, Till.

I will keep an eye on it and see how long it takes for access logging to stop again...