Swift logs in devstack are terrible

Bug #1619073 reported by clayg
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
OpenStack Object Storage (swift)
New
Undecided
Unassigned
devstack
Invalid
Undecided
Unassigned

Bug Description

Not "bad" - *terrible* -> http://logs.openstack.org/38/363838/2/check/gate-tempest-dsvm-neutron-full-ubuntu-xenial/a796242/logs/screen-s-proxy.txt.gz

There's no way other projects have logs this bad. Is that a "curl" command in there?

We should really make it better, we've even got some specific targets:

clarkb | notmyname: specifically

 * only syslog is supported
 * please do subsecond timestamp resolution
 * use apache logging format consistently so that existing tools can be used to parse those logs

Seems simple enough! In my deployments these would normally be solved by either configuring a log_custom_handlers or putting the swift services on different facilities and configuring syslog to write to separate files - but I think here we're starting swift in a screen or something?

Doesn't matter. Needs to work better.

Other data plane services like Glance might have the best example of what would be considered good default behavior.

Revision history for this message
Clark Boylan (cboylan) wrote :

I should clarify that I don't see apache log format as a requirement but whatever format that is used should be consistent. Totally fine with consisten apache log format as that would be an improvement over what we have or some other format if that is easier/better as long as it too is consistent.

In theory the nice thing about consistent apache log format is we can use preexisting tools to parse and point out interesting things about the logs.

Revision history for this message
John Dickinson (notmyname) wrote :

@clark, when you say consistent, what are you referring to? Swift's log formats are described at http://docs.openstack.org/developer/swift/logs.html.

Maybe you're referring to the other messages that are there, like the auth stuff? From what I can tell, this is coming from other middleware at DEBUG level instead of the access logs at INFO level. One way to know what's being logged by Swift and what's being logged by something else is the presence of the transaction id (txn-id). All Swift logs have that. All the other ones are not in the Swift codebase at all.

Yeah, I'll agree that the log file linked looks bad. But how do I know when I can close this bug?

Revision history for this message
clayg (clay-gerrard) wrote :
Download full text (3.1 KiB)

Clark! thanks for joining this bug - I'm still not 100% clear on that - you may need to educate me or perhaps other would have a stronger baseline knowledge here. The only log format I'm aware of from apache is request/response logging [1]

Our storage server logs are based on something like that [2], e.g.

Jul 11 17:31:15 saio object-6030: 127.0.0.1 - - [11/Jul/2016:17:31:15 +0000] "PUT /sdb3/994/AUTH_test/4-7545540342374804127/6d3d68f655563fed" 201 - "PUT http://localhost:8080/v1/AUTH_test/4-7545540342374804127/6d3d68f655563fed" "tx13648ea2c4934c5680256-005783d7e3" "proxy-server 27428" 0.2930 "-" 27954 0

... we have extra fields - so if you have specific "preexisting tools to parse and point out interesting things" ideally we could add something specific we could test against?

The proxy request log lines are different [3], e.g.

Jul 11 17:31:15 saio proxy-server: 127.0.0.1 127.0.0.1 11/Jul/2016/17/31/15 PUT /v1/AUTH_test/4-7545540342374804127/6d3d68f655563fed HTTP/1.0 201 - Hummingbird%20Client AUTH_tk1e0e05eb9... 131072 - - tx13648ea2c4934c5680256-005783d7e3 - 0.8403 - - 1468258275.055514097 1468258275.895791054 0

There's some historic reasons for that format, and AFAIK most deployments both need and depend on that format - it's the only one I ever want or need for access logs in production - we even have special documented facilities to make it easy to segregate access logs [4] - but like on my *development* machine like I just log *both* formats

Jul 11 17:31:15 saio proxy-server: STDERR: 127.0.0.1 - - [11/Jul/2016 17:31:15] "PUT /v1/AUTH_test/4-7545540342374804127/6d3d68f655563fed HTTP/1.1" 201 254 0.855121 (txn: tx13648ea2c4934c5680256-005783d7e3)

... so there's no reason we wouldn't go ahead and configure Swift on devstack to log the requests in just the format you want wherever you need it to log! But I'd be happy to prioritize here if the default documented access request/response log format in the proxy is suitable for you.

But it's not clear to me how either of these formats is relevant for like the *interesting* messages?

e.g.

Aug 30 17:30:59 hummingbird swift: ERROR with Account server 10.0.0.1:1001/sdb re: Trying to PUT /a/: #012Traceback (most recent call last):#012 File "/vagrant/swift/swift/proxy/controllers/base.py", line 1532, in _make_request#012 headers=headers, query_string=query)#012 File "/vagrant/swift/test/unit/__init__.py", line 1022, in connect#012 raise HTTPException()#012HTTPException (txn: tx16901d6ed06b4696914e7-0057c5c2d1)

e.g.

Aug 30 17:30:18 hummingbird swift: Quarantined object /tmp/tmpjU1T8M/tmp_test_object_auditor/node/sda/objects/0/a43/615cd4810e0d969889af154f7b02ba43/1472578218.87833.data: metadata content-length 10 does not match actual object size 0

^ do you have any requirements, thoughts or opinions on the "format" of unstructured messages that *aren't* request/response logging?

Cheers,

-Clay

1. https://en.wikipedia.org/wiki/Common_Log_Format
2. http://docs.openstack.org/developer/swift/logs.html#storage-node-logs
3. http://docs.openstack.org/developer/swift/logs.html#proxy-logs
4. https://github.com/openstack/swift/blob/ac81ccd948de22298f2ebd8493695b793454cd54/etc/proxy-ser...

Read more...

clayg (clay-gerrard)
tags: added: cross-project
Revision history for this message
Peter Portante (peter-a-portante) wrote :

What was the configuration that generated the tarball from the initial comment? It seems like the logs are configured expecting them to be logged via syslog(), but were just captured before they were sent to syslog().

Revision history for this message
Sean Dague (sdague) wrote :

This devstack bug was last updated over 180 days ago, as devstack
is a fast moving project and we'd like to get the tracker down to
currently actionable bugs, this is getting marked as Invalid. If the
issue still exists, please feel free to reopen it.

Changed in devstack:
status: New → Invalid
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.