OpenStack Compute (Nova)

logs in greenthreads don't log request_id

Reported by clayg on 2012-02-28
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
OpenStack Compute (nova)
High
Vish Ishaya

Bug Description

When I'm tracking stuff through the volume logs, sometimes the request_id, user_id and project_id are missing:

2012-02-28 14:33:14 DEBUG nova.rpc.common [-] received {u'_context_roles': [u'Admin', u'Admin', u'admin'], u'_context_request_id': u'req-38167a3a-c4d2-4e02-b
023-4f0f4636ec25', u'_context_read_deleted': u'no', u'args': {u'snapshot_id': None, u'volume_id': 26}, u'_context_auth_token': u'999888777666', u'_context_st
rategy': u'keystone', u'_context_is_admin': True, u'_context_project_id': u'12345', u'_context_timestamp': u'2012-02-28T19:33:14.361743', u'_context_user_id'
: u'0747b73bf9404bfaae6c810837241d8e', u'method': u'create_volume', u'_context_remote_address': u'10.6.60.211'} from (pid=3934) _safe_log /usr/lib/python2.6/
dist-packages/nova/rpc/common.py:144
2012-02-28 14:33:14 DEBUG nova.rpc.common [req-38167a3a-c4d2-4e02-b023-4f0f4636ec25 0747b73bf9404bfaae6c810837241d8e 12345] unpacked context: {'request_id':
u'req-38167a3a-c4d2-4e02-b023-4f0f4636ec25', 'user_id': u'0747b73bf9404bfaae6c810837241d8e', 'roles': [u'Admin', u'Admin', u'admin'], 'timestamp': '2012-02-2
8T19:33:14.361743', 'is_admin': True, 'auth_token': u'999888777666', 'project_id': u'12345', 'remote_address': u'10.6.60.211', 'read_deleted': u'no', 'strate
gy': u'keystone'} from (pid=3934) unpack_context /usr/lib/python2.6/dist-packages/nova/rpc/amqp.py:186
2012-02-28 14:33:14 INFO nova.volume.manager [-] volume volume-0000001a: creating
2012-02-28 14:33:14 DEBUG nova.volume.manager [-] volume volume-0000001a: creating lv of size 10G from (pid=3934) create_volume /usr/lib/python2.6/dist-packa
ges/nova/volume/manager.py:120
2012-02-28 14:33:14 DEBUG nova.volume.manager [-] volume volume-0000001a: creating export from (pid=3934) create_volume /usr/lib/python2.6/dist-packages/nova
/volume/manager.py:131
2012-02-28 14:33:14 DEBUG nova.volume.manager [-] volume volume-0000001a: created successfully from (pid=3934) create_volume /usr/lib/python2.6/dist-packages
/nova/volume/manager.py:145

You can see the [req_id user_id project_id] in the rpc.common "unpacked context" line - but the subsequent "nova.volume.manager" log lines just say [-].

This makes it really hard to troubleshoot when lots of stuff is going on...

Vish Ishaya (vishvananda) wrote :

is this fairly current code? There was an issue where elevated() was overwriting the context that we fixed a while ago.

clayg (clay-gerrard) wrote :

Fairly recent, yeah.

I pulled down master and looked at some of the log lines in volume/manager.py

and it seems like they're missing a kwarg for context:

        LOG.info(_("volume %s: creating"), volume_ref['name'])

where as in compute/manager.py you see:

        LOG.audit(_('Attaching volume %(volume_id)s to %(mountpoint)s'),
                  locals(), context=context, instance=instance_ref)

Download full text (3.2 KiB)

We have a local greenthread storage for the current context. It should be pulling the context object out of there if it isn't passed in.
Not sure what is going on here.

Vish

On Feb 28, 2012, at 7:11 PM, clayg wrote:

> Fairly recent, yeah.
>
> I pulled down master and looked at some of the log lines in
> volume/manager.py
>
> and it seems like they're missing a kwarg for context:
>
> LOG.info(_("volume %s: creating"), volume_ref['name'])
>
> where as in compute/manager.py you see:
>
> LOG.audit(_('Attaching volume %(volume_id)s to %(mountpoint)s'),
> locals(), context=context, instance=instance_ref)
>
> --
> You received this bug notification because you are subscribed to
> OpenStack Compute (nova).
> https://bugs.launchpad.net/bugs/942918
>
> Title:
> nova-volume doesn't log request_id
>
> Status in OpenStack Compute (Nova):
> New
>
> Bug description:
> When I'm tracking stuff through the volume logs, sometimes the
> request_id, user_id and project_id are missing:
>
> 2012-02-28 14:33:14 DEBUG nova.rpc.common [-] received {u'_context_roles': [u'Admin', u'Admin', u'admin'], u'_context_request_id': u'req-38167a3a-c4d2-4e02-b
> 023-4f0f4636ec25', u'_context_read_deleted': u'no', u'args': {u'snapshot_id': None, u'volume_id': 26}, u'_context_auth_token': u'999888777666', u'_context_st
> rategy': u'keystone', u'_context_is_admin': True, u'_context_project_id': u'12345', u'_context_timestamp': u'2012-02-28T19:33:14.361743', u'_context_user_id'
> : u'0747b73bf9404bfaae6c810837241d8e', u'method': u'create_volume', u'_context_remote_address': u'10.6.60.211'} from (pid=3934) _safe_log /usr/lib/python2.6/
> dist-packages/nova/rpc/common.py:144
> 2012-02-28 14:33:14 DEBUG nova.rpc.common [req-38167a3a-c4d2-4e02-b023-4f0f4636ec25 0747b73bf9404bfaae6c810837241d8e 12345] unpacked context: {'request_id':
> u'req-38167a3a-c4d2-4e02-b023-4f0f4636ec25', 'user_id': u'0747b73bf9404bfaae6c810837241d8e', 'roles': [u'Admin', u'Admin', u'admin'], 'timestamp': '2012-02-2
> 8T19:33:14.361743', 'is_admin': True, 'auth_token': u'999888777666', 'project_id': u'12345', 'remote_address': u'10.6.60.211', 'read_deleted': u'no', 'strate
> gy': u'keystone'} from (pid=3934) unpack_context /usr/lib/python2.6/dist-packages/nova/rpc/amqp.py:186
> 2012-02-28 14:33:14 INFO nova.volume.manager [-] volume volume-0000001a: creating
> 2012-02-28 14:33:14 DEBUG nova.volume.manager [-] volume volume-0000001a: creating lv of size 10G from (pid=3934) create_volume /usr/lib/python2.6/dist-packa
> ges/nova/volume/manager.py:120
> 2012-02-28 14:33:14 DEBUG nova.volume.manager [-] volume volume-0000001a: creating export from (pid=3934) create_volume /usr/lib/python2.6/dist-packages/nova
> /volume/manager.py:131
> 2012-02-28 14:33:14 DEBUG nova.volume.manager [-] volume volume-0000001a: created successfully from (pid=3934) create_volume /usr/lib/python2.6/dist-packages
> /nova/volume/manager.py:145
>
>
> You can see the [req_id user_id project_id] in the rpc.common "unpacked context" line - but the subsequent "nova.volume.manager" log lines just say [-].
>
> This makes it really hard to troubleshoot when lots of stuff is going...

Read more...

Hmm... yeah ok, thanks - I see that now. Looks legit.

I'll double check I can duplicate the issue against master - thanks for pointing me in the right direction.

Thierry Carrez (ttx) on 2012-03-15
Changed in nova:
status: New → Incomplete
clayg (clay-gerrard) wrote :

Theirry, Thanks for reminding me that this is still an issue:

2012-03-15 14:09:12 DEBUG nova.rpc.amqp [-] received {u'_context_roles': [u'admin'], u'_context_request_id': u'req-c4d4f382-5a8d-4be9-b633-21c20981973a', u'_context_read_deleted': u'no', u'args': {u'snapshot_id': None, u'volume_id': 1}, u'_context_auth_token': None, u'_context_is_admin': True, u'_context_project_id': u'dev1', u'_context_timestamp': u'2012-03-15T19:09:12.667410', u'_context_user_id': u'admin', u'method': u'create_volume', u'_context_remote_address': u'127.0.0.1'} from (pid=3947) _safe_log /opt/nova/nova/rpc/common.py:144
2012-03-15 14:09:12 DEBUG nova.rpc.amqp [req-c4d4f382-5a8d-4be9-b633-21c20981973a admin dev1] unpacked context: {'request_id': u'req-c4d4f382-5a8d-4be9-b633-21c20981973a', 'user_id': u'admin', 'roles': [u'admin'], 'timestamp': '2012-03-15T19:09:12.667410', 'is_admin': True, 'auth_token': None, 'project_id': u'dev1', 'remote_address': u'127.0.0.1', 'read_deleted': u'no'} from (pid=3947) unpack_context /opt/nova/nova/rpc/amqp.py:188
2012-03-15 14:09:12 INFO nova.volume.manager [-] volume volume-00000001: creating
2012-03-15 14:09:12 DEBUG nova.volume.manager [-] volume volume-00000001: creating lv of size 1G from (pid=3947) create_volume /opt/nova/nova/volume/manager.py:120
2012-03-15 14:09:13 DEBUG nova.volume.manager [-] volume volume-00000001: creating export from (pid=3947) create_volume /opt/nova/nova/volume/manager.py:131
2012-03-15 14:09:13 DEBUG nova.volume.manager [-] volume volume-00000001: created successfully from (pid=3947) create_volume /opt/nova/nova/volume/manager.py:145

I'll dig into it a bit more and try to figure out why the context thread local stuff isn't cutting it - I may be able to point someone in the right direction - but I was really hoping a nova dev with some experience would be able to pitch in cause this bug is real pain.

clayg (clay-gerrard) wrote :

This is up to date trunk at time of writing - commit 97eb92880e0886a3f257f32a88ba9e55b8ec8a90

Please do let me know if this is not something that others are able to duplicate?

Changed in nova:
status: Incomplete → New
clayg (clay-gerrard) wrote :

Oh ok, it wasn't so bad.

The RequestContext class sets the local when it's created (in rpc when it's unpacking it off the bus) - then the rpc passes off to it's "proxy" by spawning a greenthread to run _process_data.

So either _process_data needs to reset the local - or it can just want to RpcContext.from_dict until after it's spanwned?

Changed in nova:
status: New → In Progress
importance: Undecided → High
milestone: none → essex-rc1
assignee: nobody → Vish Ishaya (vishvananda)
summary: - nova-volume doesn't log request_id
+ greenthrads don't log request_id
summary: - greenthrads don't log request_id
+ logs in greenthreads don't log request_id

Reviewed: https://review.openstack.org/5412
Committed: http://github.com/openstack/nova/commit/4012a3f792ca5958616b31f7594f200d18665d71
Submitter: Jenkins
Branch: master

commit 4012a3f792ca5958616b31f7594f200d18665d71
Author: Vishvananda Ishaya <email address hidden>
Date: Thu Mar 15 13:02:07 2012 -0700

    Keep context for logging intact in greenthreads

     * fixes bug 942918

    Change-Id: Ia0fcf459c53b95a8675472adcfbba08014e34e5b

Changed in nova:
status: In Progress → Fix Committed
Thierry Carrez (ttx) on 2012-03-20
Changed in nova:
status: Fix Committed → Fix Released
Thierry Carrez (ttx) on 2012-04-05
Changed in nova:
milestone: essex-rc1 → 2012.1
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers