OpenStack Dashboard (Horizon)

Apache error log is throwing errors for every openstack components

Asked by Nilanjan Roy

Hi,

I am facing a weird issue. I have setup openstack grizzly on Fedora. Everything is working fine. Only problem is Apache error log is getting full because of many openstack logs. For every click in dashboard it is creating so many logs. Also same line multiple times. I have no clue why this is happening. and the log file size is growing beyond limits and at times it is growing beyond 50GB in one day :(. If anyone has faced similar issue please help.

Some lines from apache error log:
===========================================================================================
s": 20, "totalSecurityGroupsUsed": 0, "maxTotalFloatingIps": 100, "maxTotalInstances": 30, "totalCoresUsed": 2, "maxTotalRAMSize": 100000}}}
[Thu Aug 01 08:04:23.255406 2013] [:error] [pid 47768]
[Thu Aug 01 08:04:23.255498 2013] [:error] [pid 47768] RESP: [200] {'date': 'Thu, 01 Aug 2013 08:04:23 GMT', 'x-compute-request-id': 'req-4e3a1e44-267e-41 60-851e-bb03b6eb2a15', 'content-type': 'application/json', 'content-length': '1146'}
[Thu Aug 01 08:04:23.255517 2013] [:error] [pid 47768] RESP BODY: {"limits": {"rate": [{"regex": ".*", "limit": [{"next-available": "2013-08-01T07:33:38Z" , "unit": "MINUTE", "verb": "POST", "remaining": 49, "value": 50}, {"next-available": "2013-08-01T08:04:23Z", "unit": "MINUTE", "verb": "PUT", "remaining" : 50, "value": 50}, {"next-available": "2013-07-31T14:11:08Z", "unit": "MINUTE", "verb": "DELETE", "remaining": 99, "value": 100}], "uri": "\\"*\\""}, {"r egex": "^/servers", "limit": [{"next-available": "2013-08-01T08:04:23Z", "unit": "DAY", "verb": "POST", "remaining": 50, "value": 50}], "uri": "\\"*/serve rs\\""}, {"regex": ".*changes-since.*", "limit": [{"next-available": "2013-08-01T08:04:23Z", "unit": "MINUTE", "verb": "GET", "remaining": 3, "value": 3}] , "uri": "\\"*changes-since*\\""}], "absolute": {"maxServerMeta": 128, "maxPersonality": 5, "maxImageMeta": 128, "maxPersonalitySize": 10240, "maxSecurity GroupRules": 20, "maxTotalKeypairs": 100, "totalRAMUsed": 2560, "totalInstancesUsed": 2, "maxSecurityGroups": 10, "totalFloatingIpsUsed": 0, "maxTotalCore s": 20, "totalSecurityGroupsUsed": 0, "maxTotalFloatingIps": 100, "maxTotalInstances": 30, "totalCoresUsed": 2, "maxTotalRAMSize": 100000}}}
[Thu Aug 01 08:04:23.255534 2013] [:error] [pid 47768]
[Thu Aug 01 08:04:23.255614 2013] [:error] [pid 47768] RESP: [200] {'date': 'Thu, 01 Aug 2013 08:04:23 GMT', 'x-compute-request-id': 'req-4e3a1e44-267e-41 60-851e-bb03b6eb2a15', 'content-type': 'application/json', 'content-length': '1146'}
[Thu Aug 01 08:04:23.255631 2013] [:error] [pid 47768] RESP BODY: {"limits": {"rate": [{"regex": ".*", "limit": [{"next-available": "2013-08-01T07:33:38Z" , "unit": "MINUTE", "verb": "POST", "remaining": 49, "value": 50}, {"next-available": "2013-08-01T08:04:23Z", "unit": "MINUTE", "verb": "PUT", "remaining" : 50, "value": 50}, {"next-available": "2013-07-31T14:11:08Z", "unit": "MINUTE", "verb": "DELETE", "remaining": 99, "value": 100}], "uri": "\\"*\\""}, {"r egex": "^/servers", "limit": [{"next-available": "2013-08-01T08:04:23Z", "unit": "DAY", "verb": "POST", "remaining": 50, "value": 50}], "uri": "\\"*/serve rs\\""}, {"regex": ".*changes-since.*", "limit": [{"next-available": "2013-08-01T08:04:23Z", "unit": "MINUTE", "verb": "GET", "remaining": 3, "value": 3}] , "uri": "\\"*changes-since*\\""}], "absolute": {"maxServerMeta": 128, "maxPersonality": 5, "maxImageMeta": 128, "maxPersonalitySize": 10240, "maxSecurity GroupRules": 20, "maxTotalKeypairs": 100, "totalRAMUsed": 2560, "totalInstancesUsed": 2, "maxSecurityGroups": 10, "totalFloatingIpsUsed": 0, "maxTotalCore s": 20, "totalSecurityGroupsUsed": 0, "maxTotalFloatingIps": 100, "maxTotalInstances": 30, "totalCoresUsed": 2, "maxTotalRAMSize": 100000}}}
[Thu Aug 01 08:04:23.255661 2013] [:error] [pid 47768]
[Thu Aug 01 08:04:23.255743 2013] [:error] [pid 47768] RESP: [200] {'date': 'Thu, 01 Aug 2013 08:04:23 GMT', 'x-compute-request-id': 'req-4e3a1e44-267e-41 60-851e-bb03b6eb2a15', 'content-type': 'application/json', 'content-length': '1146'}
[Thu Aug 01 08:04:23.255761 2013] [:error] [pid 47768] RESP BODY: {"limits": {"rate": [{"regex": ".*", "limit": [{"next-available": "2013-08-01T07:33:38Z" , "unit": "MINUTE", "verb": "POST", "remaining": 49, "value": 50}, {"next-available": "2013-08-01T08:04:23Z", "unit": "MINUTE", "verb": "PUT", "remaining" : 50, "value": 50}, {"next-available": "2013-07-31T14:11:08Z", "unit": "MINUTE", "verb": "DELETE", "remaining": 99, "value": 100}], "uri": "\\"*\\""}, {"r egex": "^/servers", "limit": [{"next-available": "2013-08-01T08:04:23Z", "unit": "DAY", "verb": "POST", "remaining": 50, "value": 50}], "uri": "\\"*/serve rs\\""}, {"regex": ".*changes-since.*", "limit": [{"next-available": "2013-08-01T08:04:23Z", "unit": "MINUTE", "verb": "GET", "remaining": 3, "value": 3}] , "uri": "\\"*changes-since*\\""}], "absolute": {"maxServerMeta": 128, "maxPersonality": 5, "maxImageMeta": 128, "maxPersonalitySize": 10240, "maxSecurity GroupRules": 20, "maxTotalKeypairs": 100, "totalRAMUsed": 2560, "totalInstancesUsed": 2, "maxSecurityGroups": 10, "totalFloatingIpsUsed": 0, "maxTotalCore s": 20, "totalSecurityGroupsUsed": 0, "maxTotalFloatingIps": 100, "maxTotalInstances": 30, "totalCoresUsed": 2, "maxTotalRAMSize": 100000}}}
[Thu Aug 01 08:04:23.255779 2013] [:error] [pid 47768]
[Thu Aug 01 08:04:23.255861 2013] [:error] [pid 47768] RESP: [200] {'date': 'Thu, 01 Aug 2013 08:04:23 GMT', 'x-compute-request-id': 'req-4e3a1e44-267e-41 60-851e-bb03b6eb2a15', 'content-type': 'application/json', 'content-length': '1146'}
[Thu Aug 01 08:04:23.255879 2013] [:error] [pid 47768] RESP BODY: {"limits": {"rate": [{"regex": ".*", "limit": [{"next-available": "2013-08-01T07:33:38Z" , "unit": "MINUTE", "verb": "POST", "remaining": 49, "value": 50}, {"next-available": "2013-08-01T08:04:23Z", "unit": "MINUTE", "verb": "PUT", "remaining" : 50, "value": 50}, {"next-available": "2013-07-31T14:11:08Z", "unit": "MINUTE", "verb": "DELETE", "remaining": 99, "value": 100}], "uri": "\\"*\\""}, {"r egex": "^/servers", "limit": [{"next-available": "2013-08-01T08:04:23Z", "unit": "DAY", "verb": "POST", "remaining": 50, "value": 50}], "uri": "\\"*/serve rs\\""}, {"regex": ".*changes-since.*", "limit": [{"next-available": "2013-08-01T08:04:23Z", "unit": "MINUTE", "verb": "GET", "remaining": 3, "value": 3}] , "uri": "\\"*changes-since*\\""}], "absolute": {"maxServerMeta": 128, "maxPersonality": 5, "maxImageMeta": 128, "maxPersonalitySize": 10240, "maxSecurity GroupRules": 20, "maxTotalKeypairs": 100, "totalRAMUsed": 2560, "totalInstancesUsed": 2, "maxSecurityGroups": 10, "totalFloatingIpsUsed": 0, "maxTotalCore s": 20, "totalSecurityGroupsUsed": 0, "maxTotalFloatingIps": 100, "maxTotalInstances": 30, "totalCoresUsed": 2, "maxTotalRAMSize": 100000}}}
[Thu Aug 01 08:04:23.255896 2013] [:error] [pid 47768]
[Thu Aug 01 08:04:23.255973 2013] [:error] [pid 47768] RESP: [200] {'date': 'Thu, 01 Aug 2013 08:04:23 GMT', 'x-compute-request-id': 'req-4e3a1e44-267e-41 60-851e-bb03b6eb2a15', 'content-type': 'application/json', 'content-length': '1146'}
[Thu Aug 01 08:04:23.255991 2013] [:error] [pid 47768] RESP BODY: {"limits": {"rate": [{"regex": ".*", "limit": [{"next-available": "2013-08-01T07:33:38Z" , "unit": "MINUTE", "verb": "POST", "remaining": 49, "value": 50}, {"next-available": "2013-08-01T08:04:23Z", "unit": "MINUTE", "verb": "PUT", "remaining" : 50, "value": 50}, {"next-available": "2013-07-31T14:11:08Z", "unit": "MINUTE", "verb": "DELETE", "remaining": 99, "value": 100}], "uri": "\\"*\\""}, {"r egex": "^/servers", "limit": [{"next-available": "2013-08-01T08:04:23Z", "unit": "DAY", "verb": "POST", "remaining": 50, "value": 50}], "uri": "\\"*/serve rs\\""}, {"regex": ".*changes-since.*", "limit": [{"next-available": "2013-08-01T08:04:23Z", "unit": "MINUTE", "verb": "GET", "remaining": 3, "value": 3}] , "uri": "\\"*changes-since*\\""}], "absolute": {"maxServerMeta": 128, "maxPersonality": 5, "maxImageMeta": 128, "maxPersonalitySize": 10240, "maxSecurity GroupRules": 20, "maxTotalKeypairs": 100, "totalRAMUsed": 2560, "totalInstancesUsed": 2, "maxSecurityGroups": 10, "totalFloatingIpsUsed": 0, "maxTotalCore s": 20, "totalSecurityGroupsUsed": 0, "maxTotalFloatingIps": 100, "maxTotalInstances": 30, "totalCoresUsed": 2, "maxTotalRAMSize": 100000}}}
[Thu Aug 01 08:04:23.256024 2013] [:error] [pid 47768]
[Thu Aug 01 08:04:23.256123 2013] [:error] [pid 47768] RESP: [200] {'date': 'Thu, 01 Aug 2013 08:04:23 GMT', 'x-compute-request-id': 'req-4e3a1e44-267e-41 60-851e-bb03b6eb2a15', 'content-type': 'application/json', 'content-length': '1146'}
[Thu Aug 01 08:04:23.256136 2013] [:error] [pid 47768] RESP BODY: {"limits": {"rate": [{"regex": ".*", "limit": [{"next-available": "2013-08-01T07:33:38Z" , "unit": "MINUTE", "verb": "POST", "remaining": 49, "value": 50}, {"next-available": "2013-08-01T08:04:23Z", "unit": "MINUTE", "verb": "PUT", "remaining" : 50, "value": 50}, {"next-available": "2013-07-31T14:11:08Z", "unit": "MINUTE", "verb": "DELETE", "remaining": 99, "value": 100}], "uri": "\\"*\\""}, {"r egex": "^/servers", "limit": [{"next-available": "2013-08-01T08:04:23Z", "unit": "DAY", "verb": "POST", "remaining": 50, "value": 50}], "uri": "\\"*/serve rs\\""}, {"regex": ".*changes-since.*", "limit": [{"next-available": "2013-08-01T08:04:23Z", "unit": "MINUTE", "verb": "GET", "remaining": 3, "value": 3}] , "uri": "\\"*changes-since*\\""}], "absolute": {"maxServerMeta": 128, "maxPersonality": 5, "maxImageMeta": 128, "maxPersonalitySize": 10240, "maxSecurity GroupRules": 20, "maxTotalKeypairs": 100, "totalRAMUsed": 2560, "totalInstancesUsed": 2, "maxSecurityGroups": 10, "totalFloatingIpsUsed": 0, "maxTotalCore s": 20, "totalSecurityGroupsUsed": 0, "maxTotalFloatingIps": 100, "maxTotalInstances": 30, "totalCores
==================================================================================================

Question information

Language:
English Edit question
Status:
Answered
For:
OpenStack Dashboard (Horizon) Edit question
Assignee:
No assignee Edit question
Last query:
Last reply:
Revision history for this message
Lin Hua Cheng (lin-hua-cheng) said : 		#1

I may have seen this issue in Grizzly before, the number of entries logged is getting duplicated exponentially as the log is being written. I think the bug was somewhere in the pyhon-*client where the logger from client is getting registered everytime it is used.

Try setting the disable_existing_loggers = True in the local_settings.py.

Revision history for this message
Lin Hua Cheng (lin-hua-cheng) said : 		#2

Perhaps also setting the DEBUG-False will also do the trick.

Revision history for this message
Nilanjan Roy (nilanjan-r) said : 		#3

Hi
I did the changes as suggested now duplicate things are not coming. But why the logs are coming as [:error]?

[Tue Aug 06 13:22:24.541567 2013] [:error] [pid 60095]
[Tue Aug 06 13:22:24.541645 2013] [:error] [pid 60095] RESP: [200] {'date': 'Tue, 06 Aug 2013 13:22:24 GMT', 'x-compute-request-id': 'req-9155b510-1d1a-4942-9a0a-6a578ea71130', 'content-type': 'application/json', 'content-length': '1649'}
[Tue Aug 06 13:22:24.541664 2013] [:error] [pid 60095] RESP BODY: {"servers": [{"status": "ACTIVE", "updated": "2013-08-05T14:08:21Z", "hostId": "10d7dceeac017fa8f28b000a54bf6ef5ab36e286fc4277c3fce905a7", "OS-EXT-SRV-ATTR:host": "lcc5-compute2", "addresses": {"MGMTNetwork": [{"version": 4, "addr": "192.168.2.233", "OS-EXT-IPS:type": "fixed"}], "necc_net": [{"version": 4, "addr": "192.168.1.2", "OS-EXT-IPS:type": "fixed"}, {"version": 4, "addr": "12.0.0.101", "OS-EXT-IPS:type": "floating"}]}, "links": [{"href": "http://12.0.0.23:8774/v2/4f1f20fc6382456ea6fedcbf0a9e37bb/servers/7fcf7b87-9916-41df-ade1-bdb73dd515e6", "rel": "self"}, {"href": "http://12.0.0.23:8774/4f1f20fc6382456ea6fedcbf0a9e37bb/servers/7fcf7b87-9916-41df-ade1-bdb73dd515e6", "rel": "bookmark"}], "key_name": null, "image": {"id": "9ed6eb37-e846-49bf-b854-acbf9eea25a0", "links": [{"href": "http://12.0.0.23:8774/4f1f20fc6382456ea6fedcbf0a9e37bb/images/9ed6eb37-e846-49bf-b854-acbf9eea25a0", "rel": "bookmark"}]}, "OS-EXT-STS:task_state": null, "OS-EXT-STS:vm_state": "active", "OS-EXT-SRV-ATTR:instance_name": "instance-000000df", "OS-EXT-SRV-ATTR:hypervisor_hostname": "lcc5-compute2", "flavor": {"id": "2", "links": [{"href": "http://12.0.0.23:8774/4f1f20fc6382456ea6fedcbf0a9e37bb/flavors/2", "rel": "bookmark"}]}, "id": "7fcf7b87-9916-41df-ade1-bdb73dd515e6", "security_groups": [{"name": "default"}], "OS-EXT-AZ:availability_zone": "nova", "user_id": "9b6d6917eb6a4f8f99060fe15164c4dc", "name": "necc", "created": "2013-08-05T14:06:24Z", "tenant_id": "4f1f20fc6382456ea6fedcbf0a9e37bb", "OS-DCF:diskConfig": "MANUAL", "accessIPv4": "", "accessIPv6": "", "progress": 0, "OS-EXT-STS:power_state": 1, "config_drive": "", "metadata": {}}]}

Revision history for this message
Lin Hua Cheng (lin-hua-cheng) said : 		#4

I think this is because of the limitation of the WSGI application to write on stdout, all logs goes to stderr.

"This is because portable WSGI applications should not write to sys.stdout or use the 'print' statement without specifying an alternate file object besides sys.stdout as the target. This restriction can be disabled for the whole server using the WSGIRestrictStdout directive, or by mapping sys.stdout to sys.stderr at global scope within in the WSGI application script file." - https://code.google.com/p/modwsgi/wiki/DebuggingTechniques

In the horizon wsgi module it it setup to redirect sys.stdout to sys.stderr.

Revision history for this message
Lin Hua Cheng (lin-hua-cheng) said : 		#5

If you're running the application in local django server, you shouldn't see the error entry.

Can you help with this problem?

Provide an answer of your own, or ask Nilanjan Roy for more information if necessary.

To post a message you must log in.