Skip to content

Commit

Permalink
Merge pull request #35 from Rohde-Schwarz/5-add-timestamps-to-fluentd…
Browse files Browse the repository at this point in the history
…-messages

5 add timestamps to fluentd messages
  • Loading branch information
glynos authored Jun 5, 2023
2 parents 61de6f2 + e570107 commit dbc90fd
Show file tree
Hide file tree
Showing 5 changed files with 204 additions and 67 deletions.
49 changes: 40 additions & 9 deletions README.md
Original file line number Diff line number Diff line change
Expand Up @@ -104,15 +104,16 @@ def provide_more_test_information() -> dict:

The pytest CLI can be called with the following arguments in order to configure fluent-logging.

| argument | description | default |
| ---------------- | --------------------------------------------------------------------------------- | -------- |
| --session-uuid | Use a custom externally created UUID, e.g. link a CI job with the pytest session. | |
| --fluentd-host | Fluentd host address. If not provided, a local Fluentd instance will be called. | |
| --fluentd-port | Fluent host port | 24224 |
| --fluentd-tag | Set a custom Fluentd tag | 'test' |
| --fluentd-label | Set a custom Fluentd label | 'pytest' |
| --extend-logging | Extend the Python logging with a Fluent handler | False |
| --add-docstrings | Add test docstrings to testcase call messages | |
| argument | description | default |
|---------------------|------------------------------------------------------------------------------------|----------|
| --session-uuid | Use a custom externally created UUID, e.g. link a CI job with the pytest session. | |
| --fluentd-host | Fluentd host address. If not provided, a local Fluentd instance will be called. | |
| --fluentd-port | Fluent host port | 24224 |
| --fluentd-tag | Set a custom Fluentd tag | 'test' |
| --fluentd-label | Set a custom Fluentd label | 'pytest' |
| --fluentd-timestamp | Specify a Fluentd timestamp | None |
| --extend-logging | Extend the Python logging with a Fluent handler | False |
| --add-docstrings | Add test docstrings to testcase call messages | |

### Ini Configuration Support

Expand Down Expand Up @@ -214,6 +215,36 @@ pytest-fluent sends any information, e.g. stage information or logging from a te

whereat each object in the array is sent independently via Fluentd.

### Specifying a timestamp

Timestamps are added to the information if the ``--fluentd-timestamp`` option is enabled:

```python
[pytest]
addopts= --session-uuid="ac2f7600-a079-46cf-a7e0-6408b166364c" --fluentd-port=24224 --fluentd-host=localhost --fluentd-tag='dummytest' --fluentd-label='pytest' --fluentd-timestamp='@timestamp' --extend-logging
```

The timestamp is added to each message. The value is in ISO 8601 format. A sample
of the data collection from `test_addoptions.py` (as above) would look as below:

```json
[
{
"status": "start",
"stage": "session",
"sessionId": "d8f01de3-8416-4801-9406-0ea3d5cfe3c0",
"@timestamp": "2022-12-25T03:00:00.000000Z"
},
{
"status": "start",
"stage": "testcase",
"sessionId": "d8f01de3-8416-4801-9406-0ea3d5cfe3c0",
"testId": "6b444275-4450-4eff-b5d9-8355f0f99ab0",
"name": "test_fluentd_logged_parameters.py::test_base",
"@timestamp": "2022-12-25T03:00:00.100000Z"
}
]
```

## Changelog

Expand Down
2 changes: 1 addition & 1 deletion pyproject.toml
Original file line number Diff line number Diff line change
Expand Up @@ -79,4 +79,4 @@ log_level = "INFO"
log_cli = false

[tool.mypy]
ignore_missing_imports = true
ignore_missing_imports = true
49 changes: 34 additions & 15 deletions src/pytest_fluent/plugin.py
Original file line number Diff line number Diff line change
@@ -1,4 +1,5 @@
"""pytest-fluent-logging plugin definition."""
import datetime
import logging
import textwrap
import time
Expand Down Expand Up @@ -36,6 +37,7 @@ def __init__(self, config):
self._port = config.getoption("--fluentd-port")
self._tag = config.getoption("--fluentd-tag")
self._label = config.getoption("--fluentd-label")
self._timestamp = config.getoption("--fluentd-timestamp")
self._extend_logging = config.getoption("--extend-logging")
self._add_docstrings = config.getoption("--add-docstrings")
self._log_reporter = LogReport(self.config)
Expand Down Expand Up @@ -70,6 +72,12 @@ def _set_session_uid(
else:
raise ValueError("Unique identifier is not in a valid format.")

def set_timestamp_information(self, event_data: dict):
if self._timestamp is not None:
event_data.update(
{self._timestamp: f"{datetime.datetime.utcnow().isoformat()}"}
)

@property
def session_uid(
self,
Expand Down Expand Up @@ -97,6 +105,7 @@ def pytest_sessionstart(self):
"sessionId": self.session_uid,
}
data.update(get_additional_session_information())
self.set_timestamp_information(event_data=data)
event.Event(self._label, data)

def pytest_runtest_logstart(self, nodeid: str, location: typing.Tuple[int, str]):
Expand All @@ -112,6 +121,7 @@ def pytest_runtest_logstart(self, nodeid: str, location: typing.Tuple[int, str])
"name": nodeid,
}
data.update(get_additional_test_information())
self.set_timestamp_information(event_data=data)
event.Event(self._label, data)

def pytest_runtest_setup(self, item: pytest.Item):
Expand All @@ -132,8 +142,7 @@ def pytest_runtest_call(self, item: pytest.Item):
def pytest_runtest_makereport(self, item: pytest.Item, call):
report = (yield).get_result()
docstring = item.stash.get(DOCSTRING_STASHKEY, None)
report.stash = {}
report.stash[DOCSTRING_KEY] = docstring
report.stash = {DOCSTRING_KEY: docstring}

def pytest_runtest_logreport(self, report: pytest.TestReport):
"""Custom hook for logging results."""
Expand All @@ -154,6 +163,7 @@ def pytest_runtest_logreport(self, report: pytest.TestReport):
docstring = report.stash.get(DOCSTRING_KEY, None)
if docstring:
result_data.update({"docstring": docstring})
self.set_timestamp_information(event_data=result_data)
event.Event(self._label, result_data)

def pytest_runtest_logfinish(
Expand All @@ -164,15 +174,17 @@ def pytest_runtest_logfinish(
"""Custom hook for test end."""
set_stage("testcase")
if not self.config.getoption("collectonly"):
event_data = {
"status": "finish",
"stage": "testcase",
"sessionId": self.session_uid,
"testId": self.test_uid,
"name": nodeid,
}
self.set_timestamp_information(event_data=event_data)
event.Event(
self._label,
{
"status": "finish",
"stage": "testcase",
"sessionId": self.session_uid,
"testId": self.test_uid,
"name": nodeid,
},
event_data,
)

def pytest_sessionfinish(
Expand All @@ -183,14 +195,16 @@ def pytest_sessionfinish(
"""Custom hook for session end."""
set_stage("session")
if not self.config.getoption("collectonly"):
event_data = {
"status": "finish",
"duration": time.time() - self._session_start_time,
"stage": "session",
"sessionId": self.session_uid,
}
self.set_timestamp_information(event_data=event_data)
event.Event(
self._label,
{
"status": "finish",
"duration": time.time() - self._session_start_time,
"stage": "session",
"sessionId": self.session_uid,
},
event_data,
)


Expand Down Expand Up @@ -231,6 +245,11 @@ def pytest_addoption(parser):
default="pytest",
help="Custom Fluentd label (default: %(default)s)",
)
group.addoption(
"--fluentd-timestamp",
default=None,
help="Custom Fluentd timestamp (default: %(default)s)",
)
group.addoption(
"--extend-logging",
action="store_true",
Expand Down
6 changes: 6 additions & 0 deletions tests/conftest.py
Original file line number Diff line number Diff line change
Expand Up @@ -58,3 +58,9 @@ def run_mocked_pytest(runpytest):

with patch("fluent.sender.FluentSender") as sender:
yield runpytest, sender


@pytest.fixture()
def fluentd_sender():
with patch("fluent.sender.FluentSender") as sender:
yield sender.return_value
165 changes: 123 additions & 42 deletions tests/test_addoptions.py
Original file line number Diff line number Diff line change
@@ -1,53 +1,134 @@
import typing
import uuid

import pytest
from fluent.sender import EventTime

tag = "unittest"
label = "pytest"
FLUENTD_TAG = "unittest"
FLUENTD_LABEL = "pytest"


def test_fluentd_logged_parameters(run_mocked_pytest, session_uuid, logging_content):
runpytest, sender = run_mocked_pytest
FAKE_TEST_UUID = "6d653fee-0c6a-4923-9216-dfc949bd05a0"


def get_data_from_call_args(call_args, fields: typing.List[str]) -> typing.Dict:
return {field: call_args.args[2].get(field) for field in fields}


@pytest.fixture(name="monkeypatched_uuid4")
def monkeypatched_uuid4_fixture(monkeypatch):
def myuuid4():
return uuid.UUID(FAKE_TEST_UUID)

monkeypatch.setattr(uuid, "uuid4", myuuid4)


def test_fluentd_logged_parameters(
monkeypatched_uuid4, runpytest, fluentd_sender, session_uuid, logging_content
):
result = runpytest(
f"--session-uuid={session_uuid}",
f"--fluentd-tag={tag}",
f"--fluentd-label={label}",
f"--fluentd-tag={FLUENTD_TAG}",
f"--fluentd-label={FLUENTD_LABEL}",
"--extend-logging",
)
fluent_sender = sender.return_value
call_args = fluent_sender.emit_with_time.call_args_list
call_args = fluentd_sender.emit_with_time.call_args_list
result.assert_outcomes(passed=1)
assert len(call_args) > 0
for idx, call_arg in enumerate(call_args):
args = call_arg.args
if idx not in [2, 3]:
assert args[0] == label
assert isinstance(args[1], int)
else:
assert args[0] is None
assert isinstance(args[1], EventTime)
data = args[2]
assert isinstance(data, dict)
if idx in [0, 1]:
assert data.get("status") == "start"
if idx in [5, 6]:
assert data.get("status") == "finish"
assert data.get("sessionId") == str(session_uuid)
if idx in [2, 3]:
assert data.get("type") == "logging"
assert "host" in data
assert "where" in data
assert "level" in data
assert "stack_trace" in data
assert data.get("message") == logging_content
if idx in [0, 6]:
assert data.get("stage") == "session"
if idx == 6:
assert data.get("duration") > 0
if idx in [1, 2, 3, 4, 5]:
assert data.get("stage") == "testcase"
assert "testId" in data
try:
uuid.UUID(data["testId"])
except ValueError:
assert False, "Not a UUID string"
assert len(call_args) == 7

# Message 0
assert call_args[0].args[0] == FLUENTD_LABEL
assert isinstance(call_args[0].args[1], int)
message_0 = get_data_from_call_args(call_args[0], ["status", "stage", "sessionId"])
assert message_0 == {
"status": "start",
"stage": "session",
"sessionId": f"{session_uuid}",
}

# Message 1
assert call_args[1].args[0] == FLUENTD_LABEL
assert isinstance(call_args[1].args[1], int)
message_1 = get_data_from_call_args(call_args[1], ["status", "stage", "testId"])
assert message_1 == {
"status": "start",
"stage": "testcase",
"testId": FAKE_TEST_UUID,
}

# Message 2
assert call_args[2].args[0] is None
assert isinstance(call_args[2].args[1], EventTime)
message_2 = get_data_from_call_args(call_args[2], ["stage", "message"])
assert message_2 == {"stage": "testcase", "message": logging_content}
assert {"host", "where", "level", "stack_trace"}.issubset(
call_args[2].args[2].keys()
)

# Message 3
assert call_args[3].args[0] is None
assert isinstance(call_args[3].args[1], EventTime)
message_3 = get_data_from_call_args(call_args[2], ["type", "stage", "message"])
assert message_3 == {
"type": "logging",
"stage": "testcase",
"message": logging_content,
}
assert {"host", "where", "level", "stack_trace"}.issubset(
call_args[2].args[2].keys()
)

# Message 4
assert call_args[4].args[0] == FLUENTD_LABEL
assert isinstance(call_args[4].args[1], int)
assert call_args[4].args[2].get("stage") == "testcase"

# Message 5
assert call_args[5].args[0] == FLUENTD_LABEL
assert isinstance(call_args[5].args[1], int)
message_5 = get_data_from_call_args(call_args[5], ["status", "stage"])
assert message_5 == {"status": "finish", "stage": "testcase"}

# Message 6
assert call_args[6].args[0] == FLUENTD_LABEL
assert isinstance(call_args[6].args[1], int)
message_6 = get_data_from_call_args(call_args[6], ["status", "stage"])
assert message_6 == {"status": "finish", "stage": "session"}
assert call_args[6].args[2].get("duration") > 0


def is_pytest_message(args):
return args[0] is not None and args[0] == "pytest"


def test_fluentd_with_options_and_timestamp_enabled_shows_timestamp_field_in_output(
runpytest, fluentd_sender, session_uuid
):
result = runpytest(
f"--session-uuid={session_uuid}",
f"--fluentd-tag={FLUENTD_TAG}",
f"--fluentd-label={FLUENTD_LABEL}",
f"--fluentd-timestamp=@timestamp",
"--extend-logging",
)
result.assert_outcomes(passed=1)
call_args = fluentd_sender.emit_with_time.call_args_list
assert len(call_args) == 7

for call_arg in filter(is_pytest_message, call_args):
assert "@timestamp" in call_arg.args[2]


def test_fluentd_with_timestamp_enabled_shows_timestamp_field_in_output(
runpytest, fluentd_sender, session_uuid
):
result = runpytest(
f"--session-uuid={session_uuid}",
f"--fluentd-timestamp=@timestamp",
)
result.assert_outcomes(passed=1)
call_args = fluentd_sender.emit_with_time.call_args_list
assert len(call_args) == 5

for call_arg in filter(is_pytest_message, call_args):
assert "@timestamp" in call_arg.args[2]

0 comments on commit dbc90fd

Please sign in to comment.