Apache error logs contains non-error messages

[Aakash Soni]

In the file /var/log/apache2/horizon.error.log there are many lines that are not errors:

[Fri Apr 17 14:49:32.604840 2015] [:error] [pid 28933:tid 140515448411904] Login successful for user "admin".
[Fri Apr 17 13:04:25.892490 2015] [:error] [pid 28933:tid 140515448411904] Logging out user "admin".
[Fri Apr 17 06:08:22.662311 2015] [:error] [pid 28933:tid 140515414841088] Creating user with name "demo"
[Fri Apr 17 14:50:51.395871 2015] [:error] [pid 28933:tid 140515414841088] Project switch successful for user "admin".
[Thu Apr 16 08:40:23.971582 2015] [:error] [pid 28933:tid 140515473590016] Deleted token 9295d3bcfb74cda6703b91a94487072c

All these messages are logged with class 'ERROR'. As these messages are success messages they must be of type 'INFO'

To reproduce the bug - Login to the dashboard and then check the horizon.error.log, You'll find the login success message in the log with class [:error]

[Timur Sufiev (tsufiev-x)]

Aakash, AFAIK that's the inevitable behavior of Django handler = 'console', every logging message sent there receives an 'error' tag in Apache logs. Two solutions I'm aware of are either send messages to File-based handler, or to Syslog-based handler.

[Timur Sufiev (tsufiev-x)]

Nevertheless, if there is a solution I still don't know about, it would be great to implement it :).

[Lin Hua Cheng (lin-hua-cheng)]

Isn't this more of apache configuration related?

It is setup as:
    ErrorLog /var/log/%APACHE_NAME%/horizon_error.log
    LogLevel warn
    CustomLog /var/log/%APACHE_NAME%/horizon_access.log combined

https://github.com/openstack-dev/devstack/blob/231a3e55876f299252b0bea4bcb6487ba501d09b/files/apache-horizon.template#L34

[Pilar Gomez (pgomezmoy)]

I can confirm the error.
Apache log level looks fine, but the horizon-related logs seems to be coming out as errors all the time:

[Wed Mar 15 10:04:29.260787 2017] [:error] [pid 39]
[Wed Mar 15 10:04:29.261830 2017] [:error] [pid 39]
[Wed Mar 15 10:04:29.261858 2017] [:error] [pid 39] REQ: curl -i http://10.142.0.1:9696/v2.0/floatingips.json?tenant_id=f5e2907a00314b9885cf01f5766f38d1 -X GET -H "User-Agent: python-neutronclient" -H "X-Auth-Token: 18c4f815438542c5bd05bb864d0dece1"
[Wed Mar 15 10:04:29.261872 2017] [:error] [pid 39]
[Wed Mar 15 10:04:29.291733 2017] [:error] [pid 39] RESP:200 {'date': 'Wed, 15 Mar 2017 15:04:29 GMT', 'content-length': '19', 'content-type': 'application/json; charset=UTF-8', 'connection': 'keep-alive'} {"floatingips": []}
[Wed Mar 15 10:04:29.291769 2017] [:error] [pid 39]
[Wed Mar 15 10:04:29.291971 2017] [:error] [pid 39] port_list(): params={'tenant_id': u'f5e2907a00314b9885cf01f5766f38d1'}
[Wed Mar 15 10:04:29.292183 2017] [:error] [pid 39]
[Wed Mar 15 10:04:29.292196 2017] [:error] [pid 39] REQ: curl -i http://10.142.0.1:9696/v2.0/ports.json?tenant_id=f5e2907a00314b9885cf01f5766f38d1 -X GET -H "User-Agent: python-neutronclient" -H "X-Auth-Token: 18c4f815438542c5bd05bb864d0dece1"
[Wed Mar 15 10:04:29.292199 2017] [:error] [pid 39]
[Wed Mar 15 10:04:29.404507 2017] [:error] [pid 39] RESP:200 {'date': 'Wed, 15 Mar 2017 15:04:29 GMT', 'content-length': '13', 'content-type': 'application/json; charset=UTF-8', 'connection': 'keep-alive'} {"ports": []}
[Wed Mar 15 10:04:29.404546 2017] [:error] [pid 39]
[Wed Mar 15 10:04:29.404887 2017] [:error] [pid 39]
[Wed Mar 15 10:04:29.404938 2017] [:error] [pid 39] REQ: curl -i http://10.142.0.1:9696/v2.0/quotas/f5e2907a00314b9885cf01f5766f38d1.json -X GET -H "User-Agent: python-neutronclient" -H "X-Auth-Token: 18c4f815438542c5bd05bb864d0dece1"
[Wed Mar 15 10:04:29.404946 2017] [:error] [pid 39]
[Wed Mar 15 10:04:29.437469 2017] [:error] [pid 39] RESP:200 {'date': 'Wed, 15 Mar 2017 15:04:29 GMT', 'content-length': '84', 'content-type': 'application/json; charset=UTF-8', 'connection': 'keep-alive'} {"quota": {"port": 50, "subnet": 10, "floatingip": 50, "network": 10, "router": 10}}
[Wed Mar 15 10:04:29.437516 2017] [:error] [pid 39]
[Wed Mar 15 10:04:33.204418 2017] [:error] [pid 39] adding enforcer for service: compute
[Wed Mar 15 10:04:33.204668 2017] [:error] [pid 39] adding enforcer for service: network
[Wed Mar 15 10:04:33.204811 2017] [:error] [pid 39] adding enforcer for service: image
[Wed Mar 15 10:04:33.205092 2017] [:error] [pid 39] adding enforcer for service: telemetry
[Wed Mar 15 10:04:33.205211 2017] [:error] [pid 39] adding enforcer for service: volume
[Wed Mar 15 10:04:33.205504 2017] [:error] [pid 39] adding enforcer for service: orchestration
[Wed Mar 15 10:04:33.205683 2017] [:error] [pid 39] adding enforcer for service: identity

[Akihiro Motoki (amotoki)]

I think this is the limitation of apache wsgi.
Apache log level is not referred to in WSGI application (horizon in this case). Logging level of WSGI application needs to be configured separately.

My suggestions are:
- Configure Django logging depending on your desired log level https://docs.djangoproject.com/en/2.0/topics/logging/
- Use '%(levelname)s %(name)s %(message)s' as Django log format
- Use ErrorLogFormat "%{cu}t %M" for Apache logging

[Akihiro Motoki (amotoki)]

From the above configuration I got the following logs

2018-02-09 18:39:23.570932 DEBUG openstack_auth.backend Beginning user authentication
2018-02-09 18:39:23.571544 DEBUG openstack_auth.plugin.password Attempting to authenticate for admin
2018-02-09 18:39:23.937913 DEBUG openstack_auth.backend Authentication completed.
2018-02-09 18:39:23.938060 INFO openstack_auth.forms Login successful for user "admin" using domain "Default", remote address 172.27.207.5.

[Akihiro Motoki (amotoki)]

There is no good solution that horizon can do more and there are possible configurations.
I am marking this as Won't Fix.