Skip to content

Navigation Menu

Sign in
Appearance settings

Search code, repositories, users, issues, pull requests...

Provide feedback

We read every piece of feedback, and take your input very seriously.

Saved searches

Use saved searches to filter your results more quickly

Appearance settings

feat: OpenTelemetry trace/spanID integration for Python handlers #889

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 17 commits into from
May 22, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
62 changes: 56 additions & 6 deletions 62 google/cloud/logging_v2/handlers/_helpers.py
Original file line number Diff line number Diff line change
Expand Up @@ -24,6 +24,8 @@
except ImportError: # pragma: NO COVER
flask = None

import opentelemetry.trace

from google.cloud.logging_v2.handlers.middleware.request import _get_django_request

_DJANGO_CONTENT_LENGTH = "CONTENT_LENGTH"
Expand Down Expand Up @@ -191,23 +193,71 @@ def _parse_xcloud_trace(header):
return trace_id, span_id, trace_sampled


def _retrieve_current_open_telemetry_span():
"""Helper to retrieve trace, span ID, and trace sampled information from the current
OpenTelemetry span.

Returns:
Tuple[Optional[str], Optional[str], bool]:
Data related to the current trace_id, span_id, and trace_sampled for the
current OpenTelemetry span. If a span is not found, return None/False for all
fields.
"""
span = opentelemetry.trace.get_current_span()
if span != opentelemetry.trace.span.INVALID_SPAN:
context = span.get_span_context()
trace_id = opentelemetry.trace.format_trace_id(context.trace_id)
span_id = opentelemetry.trace.format_span_id(context.span_id)
trace_sampled = context.trace_flags.sampled

return trace_id, span_id, trace_sampled

return None, None, False


def get_request_data():
"""Helper to get http_request and trace data from supported web
frameworks (currently supported: Flask and Django).
frameworks (currently supported: Flask and Django), as well as OpenTelemetry. Attempts
to retrieve trace/spanID from OpenTelemetry first, before going to Traceparent then XCTC.
HTTP request data is taken from a supporting web framework (currently Flask or Django).
Because HTTP request data is decoupled from OpenTelemetry, it is possible to get as a
return value the HTTP request from the web framework of choice, and trace/span data from
OpenTelemetry, even if trace data is present in the HTTP request headers.

Returns:
Tuple[Optional[dict], Optional[str], Optional[str], bool]:
Data related to the current http request, trace_id, span_id, and trace_sampled
for the request. All fields will be None if a http request isn't found.
"""

(
otel_trace_id,
otel_span_id,
otel_trace_sampled,
) = _retrieve_current_open_telemetry_span()

# Get HTTP request data
checkers = (
get_request_data_from_django,
get_request_data_from_flask,
)

for checker in checkers:
http_request, trace_id, span_id, trace_sampled = checker()
if http_request is not None:
return http_request, trace_id, span_id, trace_sampled
http_request, http_trace_id, http_span_id, http_trace_sampled = (
None,
None,
None,
False,
)

return None, None, None, False
for checker in checkers:
http_request, http_trace_id, http_span_id, http_trace_sampled = checker()
if http_request is None:
http_trace_id, http_span_id, http_trace_sampled = None, None, False
else:
break

# otel_trace_id existing means the other return values are non-null
if otel_trace_id:
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If there is no http request data, do we reuse the http_request from last request for otel?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If there is no http request data I have it set to null value.

return http_request, otel_trace_id, otel_span_id, otel_trace_sampled
else:
return http_request, http_trace_id, http_span_id, http_trace_sampled
1 change: 1 addition & 0 deletions 1 noxfile.py
Original file line number Diff line number Diff line change
Expand Up @@ -63,6 +63,7 @@
"google-cloud-pubsub",
"google-cloud-storage",
"google-cloud-testutils",
"opentelemetry-sdk",
]
SYSTEM_TEST_LOCAL_DEPENDENCIES: List[str] = []
SYSTEM_TEST_DEPENDENCIES: List[str] = []
Expand Down
1 change: 1 addition & 0 deletions 1 owlbot.py
Original file line number Diff line number Diff line change
Expand Up @@ -93,6 +93,7 @@ def place_before(path, text, *before_text, escape=None):
"google-cloud-pubsub",
"google-cloud-storage",
"google-cloud-testutils",
"opentelemetry-sdk"
],
unit_test_external_dependencies=["flask", "webob", "django"],
samples=True,
Expand Down
1 change: 1 addition & 0 deletions 1 setup.py
Original file line number Diff line number Diff line change
Expand Up @@ -44,6 +44,7 @@
"google-cloud-audit-log >= 0.1.0, < 1.0.0dev",
"google-cloud-core >= 2.0.0, <3.0.0dev",
"grpc-google-iam-v1 >=0.12.4, <1.0.0dev",
"opentelemetry-api >= 1.0.0",
"proto-plus >= 1.22.0, <2.0.0dev",
"proto-plus >= 1.22.2, <2.0.0dev; python_version>='3.11'",
"protobuf>=3.19.5,<5.0.0dev,!=3.20.0,!=3.20.1,!=4.21.0,!=4.21.1,!=4.21.2,!=4.21.3,!=4.21.4,!=4.21.5",
Expand Down
57 changes: 57 additions & 0 deletions 57 tests/system/test_system.py
Original file line number Diff line number Diff line change
Expand Up @@ -19,6 +19,7 @@
import numbers
import os
import pytest
import sys
import unittest
import uuid

Expand Down Expand Up @@ -117,6 +118,25 @@ def setUpModule():
)


def _cleanup_otel_sdk_modules(f):
"""
Decorator to delete all references to opentelemetry SDK modules after a
testcase is run. Test case should import opentelemetry SDK modules inside
the function. This is to test situations where the opentelemetry SDK
is not imported at all.
"""

def wrapped(*args, **kwargs):
f(*args, **kwargs)

# Deleting from sys.modules should be good enough in this use case
for module_name in list(sys.modules.keys()):
if module_name.startswith("opentelemetry.sdk"):
sys.modules.pop(module_name)

return wrapped


class TestLogging(unittest.TestCase):
JSON_PAYLOAD = {
"message": "System test: test_log_struct",
Expand Down Expand Up @@ -662,6 +682,43 @@ def test_log_root_handler(self):
self.assertEqual(len(entries), 1)
self.assertEqual(entries[0].payload, expected_payload)

@_cleanup_otel_sdk_modules
def test_log_handler_otel_integration(self):
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is it possible to also add a system test without the otel sdk imported?

I'm not exactly sure what that should look like, but I want to make sure we have coverage of the situation where otel isn't used at all

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is it possible to create another file for the newly added system tests, so that the existing TCs aren't importing otel?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah, you can add an extra file. Or just import within the test functions. Or use a test class. Whatever seems cleanest

Does Otel behave any differently based on having the module installed? Or is import state the important part?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I actually managed to resolve this by creating a decorator that deletes the otel SDK imports after the test case gets run. I don't think it's perfect but it feels good enough.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ok great! Do you have any test cases that test _retrieve_current_open_telemetry_span without otel included?

# Doing OTel imports here to not taint the other tests with OTel SDK imports
from opentelemetry import trace
from opentelemetry.sdk.trace import TracerProvider

LOG_MESSAGE = "This is a test of OpenTelemetry"
LOGGER_NAME = "otel-integration"
handler_name = self._logger_name(LOGGER_NAME)

handler = CloudLoggingHandler(
Config.CLIENT, name=handler_name, transport=SyncTransport
)
# only create the logger to delete, hidden otherwise
logger = Config.CLIENT.logger(handler.name)
self.to_delete.append(logger)

# Set up OTel SDK
provider = TracerProvider()

tracer = provider.get_tracer("test_system")
with tracer.start_as_current_span("test-span") as span:
context = span.get_span_context()
expected_trace_id = f"projects/{Config.CLIENT.project}/traces/{trace.format_trace_id(context.trace_id)}"
expected_span_id = trace.format_span_id(context.span_id)
expected_tracesampled = context.trace_flags.sampled

cloud_logger = logging.getLogger(LOGGER_NAME)
cloud_logger.addHandler(handler)
cloud_logger.warning(LOG_MESSAGE)

entries = _list_entries(logger)
self.assertEqual(len(entries), 1)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do we need to consider instrumentation source entry here? http://go/cdpe-ops-logentry-changes-source

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Whether or not the instrumentation source entry gets added depends on whether or not the global variable google.cloud.logging_v2._instrumentation_emitted is true (see

_instrumentation_emitted = False
). When I was running the system tests locally I found that if I ran the entire test suite this case would pass, but if I ran just this test case the instrumentation source entry would be there and it would fail.

self.assertEqual(entries[0].trace, expected_trace_id)
self.assertEqual(entries[0].span_id, expected_span_id)
self.assertTrue(entries[0].trace_sampled, expected_tracesampled)

def test_create_metric(self):
METRIC_NAME = "test-create-metric%s" % (_RESOURCE_ID,)
metric = Config.CLIENT.metric(
Expand Down
41 changes: 41 additions & 0 deletions 41 tests/unit/handlers/__init__.py
Original file line number Diff line number Diff line change
Expand Up @@ -11,3 +11,44 @@
# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
# See the License for the specific language governing permissions and
# limitations under the License.


# Utility functions to setup mock OpenTelemetry spans, needed by multiple test
# suites.

import contextlib

import opentelemetry.context
import opentelemetry.trace

from opentelemetry.trace import NonRecordingSpan
from opentelemetry.trace.span import TraceFlags

_OTEL_SPAN_CONTEXT_TRACE_ID = 0x123456789123456789
_OTEL_SPAN_CONTEXT_SPAN_ID = 0x123456789
_OTEL_SPAN_CONTEXT_TRACEFLAGS = TraceFlags(TraceFlags.SAMPLED)

_EXPECTED_OTEL_TRACE_ID = "00000000000000123456789123456789"
_EXPECTED_OTEL_SPAN_ID = "0000000123456789"
_EXPECTED_OTEL_TRACESAMPLED = True


@contextlib.contextmanager
def _setup_otel_span_context():
"""Sets up a nonrecording OpenTelemetry span with a mock span context that gets returned
by opentelemetry.trace.get_current_span, and returns it as a contextmanager
"""
span_context = opentelemetry.trace.SpanContext(
_OTEL_SPAN_CONTEXT_TRACE_ID,
_OTEL_SPAN_CONTEXT_SPAN_ID,
False,
trace_flags=_OTEL_SPAN_CONTEXT_TRACEFLAGS,
)
ctx = opentelemetry.trace.set_span_in_context(NonRecordingSpan(span_context))
tracer = opentelemetry.trace.NoOpTracer()
token = opentelemetry.context.attach(ctx)
try:
with tracer.start_as_current_span("test-span", context=ctx):
yield
finally:
opentelemetry.context.detach(token)
143 changes: 143 additions & 0 deletions 143 tests/unit/handlers/test__helpers.py
Original file line number Diff line number Diff line change
Expand Up @@ -16,6 +16,13 @@

import mock

from tests.unit.handlers import (
_setup_otel_span_context,
_EXPECTED_OTEL_TRACE_ID,
_EXPECTED_OTEL_SPAN_ID,
_EXPECTED_OTEL_TRACESAMPLED,
)

_FLASK_TRACE_ID = "flask0id"
_FLASK_SPAN_ID = "span0flask"
_FLASK_HTTP_REQUEST = {"requestUrl": "https://flask.palletsprojects.com/en/1.1.x/"}
Expand Down Expand Up @@ -356,6 +363,120 @@ def test_wo_libraries(self):
output = self._call_fut()
self.assertEqual(output, (None, None, None, False))

def test_otel_span_exists_no_request(self):
flask_expected = (None, None, None, False)
django_expected = (None, None, None, False)

with _setup_otel_span_context():
_, _, output = self._helper(django_expected, flask_expected)
self.assertEqual(
output,
(
None,
_EXPECTED_OTEL_TRACE_ID,
_EXPECTED_OTEL_SPAN_ID,
_EXPECTED_OTEL_TRACESAMPLED,
),
)

def test_otel_span_exists_django_request(self):
django_expected = (
_DJANGO_HTTP_REQUEST,
_DJANGO_TRACE_ID,
_DJANGO_SPAN_ID,
False,
)
flask_expected = (None, None, None, False)

with _setup_otel_span_context():
_, _, output = self._helper(django_expected, flask_expected)
self.assertEqual(
output,
(
_DJANGO_HTTP_REQUEST,
_EXPECTED_OTEL_TRACE_ID,
_EXPECTED_OTEL_SPAN_ID,
_EXPECTED_OTEL_TRACESAMPLED,
),
)

def test_otel_span_exists_flask_request(self):
django_expected = (None, None, None, False)
flask_expected = (_FLASK_HTTP_REQUEST, _FLASK_TRACE_ID, _FLASK_SPAN_ID, False)

with _setup_otel_span_context():
_, _, output = self._helper(django_expected, flask_expected)
self.assertEqual(
output,
(
_FLASK_HTTP_REQUEST,
_EXPECTED_OTEL_TRACE_ID,
_EXPECTED_OTEL_SPAN_ID,
_EXPECTED_OTEL_TRACESAMPLED,
),
)

def test_otel_span_exists_both_django_and_flask(self):
django_expected = (
_DJANGO_HTTP_REQUEST,
_DJANGO_TRACE_ID,
_DJANGO_SPAN_ID,
False,
)
flask_expected = (_FLASK_HTTP_REQUEST, _FLASK_TRACE_ID, _FLASK_SPAN_ID, False)

with _setup_otel_span_context():
_, _, output = self._helper(django_expected, flask_expected)

# Django wins
self.assertEqual(
output,
(
_DJANGO_HTTP_REQUEST,
_EXPECTED_OTEL_TRACE_ID,
_EXPECTED_OTEL_SPAN_ID,
_EXPECTED_OTEL_TRACESAMPLED,
),
)

def test_no_otel_span_no_requests(self):
flask_expected = (None, None, None, False)
django_expected = (None, None, None, False)
_, _, output = self._helper(django_expected, flask_expected)
self.assertEqual(output, (None, None, None, False))

def test_no_otel_span_django_request(self):
django_expected = (
_DJANGO_HTTP_REQUEST,
_DJANGO_TRACE_ID,
_DJANGO_SPAN_ID,
False,
)
flask_expected = (None, None, None, False)
_, _, output = self._helper(django_expected, flask_expected)
self.assertEqual(output, django_expected)

def test_no_otel_span_flask_request(self):
django_expected = (None, None, None, False)
flask_expected = (_FLASK_HTTP_REQUEST, _FLASK_TRACE_ID, _FLASK_SPAN_ID, False)
_, _, output = self._helper(django_expected, flask_expected)

# Django wins
self.assertEqual(output, flask_expected)

def test_no_otel_span_both_django_and_flask(self):
django_expected = (
_DJANGO_HTTP_REQUEST,
_DJANGO_TRACE_ID,
_DJANGO_SPAN_ID,
False,
)
flask_expected = (_FLASK_HTTP_REQUEST, _FLASK_TRACE_ID, _FLASK_SPAN_ID, False)
_, _, output = self._helper(django_expected, flask_expected)

# Django wins
self.assertEqual(output, django_expected)


class Test__parse_xcloud_trace(unittest.TestCase):
@staticmethod
Expand Down Expand Up @@ -477,3 +598,25 @@ def test_invalid_headers(self):
self.assertIsNone(trace_id)
self.assertIsNone(span_id)
self.assertEqual(sampled, False)


class Test__parse_open_telemetry_data(unittest.TestCase):
@staticmethod
def _call_fut():
from google.cloud.logging_v2.handlers import _helpers

trace, span, sampled = _helpers._retrieve_current_open_telemetry_span()
return trace, span, sampled

def test_no_op(self):
trace_id, span_id, sampled = self._call_fut()
self.assertIsNone(trace_id)
self.assertIsNone(span_id)
self.assertEqual(sampled, False)

def test_span_exists(self):
with _setup_otel_span_context():
trace_id, span_id, sampled = self._call_fut()
self.assertEqual(trace_id, _EXPECTED_OTEL_TRACE_ID)
self.assertEqual(span_id, _EXPECTED_OTEL_SPAN_ID)
self.assertEqual(sampled, _EXPECTED_OTEL_TRACESAMPLED)
Loading
Morty Proxy This is a proxified and sanitized view of the page, visit original site.