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

Discussion in 'Installation/Configuration' started by cbj4074, Jan 4, 2017.

  1. cbj4074

    cbj4074 Member

    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!
     
  2. till

    till Super Moderator Staff Member ISPConfig Developer

    Yes, the time when the cronjob is run matters for the calculation, so please wait for the next scheduled run to see if it is ok then.
     
  3. cbj4074

    cbj4074 Member

    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!
     
  4. till

    till Super Moderator Staff Member ISPConfig Developer

    Do you see the current log data in /var/log/ispconfig/httpd/domain.tld ? Are the bind mounts for all sites in /etc/fstab ?
     
  5. cbj4074

    cbj4074 Member

    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... :/
     
  6. till

    till Super Moderator Staff Member ISPConfig Developer

    Ok, so we have to go trough the config step by step. This is a nginx web serevr, right? In that case, each website vhost should have a line like this:

    access_log /var/log/ispconfig/httpd/<tmpl_var name='domain'>/access.log combined;

    <tmpl_var name='domain'> should be your domain name. This mans that there should be an up to date access.log in the folder /var/log/ispconfig/httpd/domain.tld. If this log does not contain any data while the config line is in the vhost, then there must be some kind of internal problem in nginx.

    The bind mount in fstab is responsible that the log directory in the website tree shows the same data.

    The rotation of the files is then made by ispconfig, but if the original access.log does not contain any data, the rotated logs can not contain data as well.
     
  7. cbj4074

    cbj4074 Member

    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.
     
  8. cbj4074

    cbj4074 Member

    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...
     

Share This Page