Logging fails with two related virtual hosts

[dirkroorda]

In a setup where a wsgi app is served both over http and https one is tempted to do this

<VirtualHost *:80>
  ServerName «SERVER_URL»

  WSGIDaemonProcess web2py user=apache group=apache threads=5

  WSGIProcessGroup web2py
  WSGIScriptAlias / /opt/web-apps/web2py/wsgihandler.py
  WSGIPassAuthorization On

  LogLevel warn
  ErrorLog /var/log/httpd/wsgi_error
  CustomLog /var/log/httpd/wsgi_access common

  <Directory /opt/web-apps/web2py>
    AllowOverride None
    Require all denied
    <Files wsgihandler.py>
        Require all granted
    </Files>
  </Directory>

 </VirtualHost>

<VirtualHost *:443>
  ServerName «SERVER_URL»
  WSGIProcessGroup web2py
  WSGIScriptAlias / /opt/web-apps/web2py/wsgihandler.py
  WSGIPassAuthorization On

  LogLevel warn
  ErrorLog /var/log/httpd/wsgi_error
  CustomLog /var/log/httpd/wsgi_access common

  <Directory /opt/web-apps/web2py>
    AllowOverride None
    Require all denied
    <Files wsgihandler.py>
        Require all granted
    </Files>
  </Directory>

# plus SSL stuff ...

  CustomLog logs/wsgi_request \
          "%t %h %{SSL_PROTOCOL}x %{SSL_CIPHER}x \"%r\" %b"
</VirtualHost>

This is how the wsgi docs recommend it (https://modwsgi.readthedocs.io/en/develop/configuration-directives/WSGIDaemonProcess.html). It is stated there that:

When WSGIDaemonProcess is associated with a virtual host, the error log associated with that virtual host will be used for all Apache error log output from mod_wsgi rather than it appear in the main Apache error log.

But what I saw was that no messages from within the wsgi app when served over :443 ever land in any log file. I did see more generic wsgi info messages about initialization though.

Apart from this the app works, till the last bit of it, only the logging does not come through.

This is how I managed to see my debug messages eventually: I put the line with WSGIDaemonProcess in the wsgi.conf file, and removed it from any virtual host.

I only file this as an issue because I have chased half the world to discover this, being not terribly familiar with WSGI and Web2Py. So for a long time I thought that this was something where the deeper magic of wsgi clashed with the deeper magic of Web2Py, until I started experimenting with the minimal wsgi app found here: https://github.com/GrahamDumpleton/mod_wsgi/blob/develop/docs/user-guides/debugging-techniques.rst#displaying-request-environment (thanks @GrahamDumpleton !). This pinpointed the problem as being in the config file, and from then it was a matter of quick elimination.

[GrahamDumpleton]

That minimal WSGI app you are linking to doesn't actually log anything so I wouldn't expect it to show anything in the error log. Is that really what you are using to test?

If you set LogLevel to info, does mod_wsgi at least output any internal messages about WSGI script loading etc?

As to web2py, it isn't regarded as a very WSGI friendly web framework and personally I wouldn't recommend it. If using it, I would not be surprised if it breaks all logging when run under mod_wsgi.

[dirkroorda]

The minimal WSGI script did not give any clues itself, but it helped me to rule out a bunch of things. I am working on an SELinix system which also has a lot of room to make mistakes. I was worried that Web2Py had redirected sys.stderr, so I looked in the gluon code, and saw that it does, only not for wsgi. Having the test script ruled out all that. Combined with the complete absence of other people having this problem too, there was really one thing that could be the culprit, the apache configuration.

Normally I'm much quicker to find things like this, but I was baffled by the fact that on the one hand I declare the WSGIDaemonProcess for one host, and it works for both, and on the other hand I declare the logging for both hosts, and it does not work for at least one of them.

The expectation is that things you declare for a host work for that host and not others, and also that those things work completely.

In earlier stages I put the WSGIDaemonProcess directive in both hosts, because I thought: "this can't be right", but then I stumbled on apache not wanting to start.

So the thing is: without being intimate with the workings of apache and wsgi, I was thinking along lines I found logical, but eventually it was wrong.

I have read this documentation many times: https://modwsgi.readthedocs.io/en/master/user-guides/debugging-techniques.html and I think it would helped me tremendously if there was a paragraph there that explains that logging only works for the virtual host that has the WSGIDaemonProcess directive and not in other virtual hosts that use the same daemon process by the WSGIProcessGroup directive. Just above the heading Displaying Request Environment would be an excellent place.

By the way: delving deeper in mod_wsgi and reading more of the docs made me realise what a sophisticated piece of work this is! Thanks for that.

[dirkroorda]

If you set LogLevel to info, does mod_wsgi at least output any internal messages about WSGI script loading etc?

Yes. And that increased my confusion. I thought: web2py is hijacking sys.stderr after that, and dumps messages emitted from my application code into a sink.

[dirkroorda]

As to web2py, it isn't regarded as a very WSGI friendly web framework and personally I wouldn't recommend it. If using it, I would not be surprised if it breaks all logging when run under mod_wsgi.

I have used it for my first webapp 8 years ago which is still in productive use. For later apps I used first bottle and later flask. I feel much more comfortable with those frameworks indeed. The idea of not having too much magic between my code and the request and the database I find very appealing.

But, luckily, it does not break the logging after all. And I saw that

sys.stderr.write(msg)

has the same effect as

request.wsgi.environ["wsgi.errors"].write(msg)

so it behaves itself.