|
2 | 2 | import logging |
3 | 3 | import time |
4 | 4 | import pytest |
| 5 | +from datetime import datetime, timezone |
5 | 6 |
|
6 | 7 | from eval_protocol.log_utils.elasticsearch_direct_http_handler import ElasticsearchDirectHttpHandler |
7 | 8 | from eval_protocol.log_utils.elasticsearch_client import ElasticsearchClient |
@@ -514,3 +515,91 @@ def test_elasticsearch_direct_http_handler_rollout_id_from_extra_overrides_env( |
514 | 515 | ) |
515 | 516 |
|
516 | 517 | print(f"Successfully verified rollout_id override: extra '{extra_rollout_id}' overrode environment '{rollout_id}'") |
| 518 | + |
| 519 | + |
| 520 | +@pytest.mark.skipif(os.environ.get("CI") == "true", reason="Only run this test locally (skipped in CI)") |
| 521 | +def test_elasticsearch_direct_http_handler_timestamp_format( |
| 522 | + elasticsearch_client: ElasticsearchClient, test_logger: logging.Logger, rollout_id: str |
| 523 | +): |
| 524 | + """Test that ElasticsearchDirectHttpHandler formats timestamps correctly with UTC timezone.""" |
| 525 | + |
| 526 | + # Generate a unique test message |
| 527 | + test_message = f"Timestamp format test message at {time.time()}" |
| 528 | + |
| 529 | + # Record the time before logging to compare with the timestamp |
| 530 | + before_log_time = datetime.now(timezone.utc) |
| 531 | + |
| 532 | + # Send the log message |
| 533 | + test_logger.info(test_message) |
| 534 | + |
| 535 | + # Record the time after logging |
| 536 | + after_log_time = datetime.now(timezone.utc) |
| 537 | + |
| 538 | + # Give Elasticsearch a moment to process the document |
| 539 | + time.sleep(3) |
| 540 | + |
| 541 | + # Search for the document using the client |
| 542 | + search_results = elasticsearch_client.search_by_match("message", test_message, size=1) |
| 543 | + |
| 544 | + # Assert that we found our log message |
| 545 | + assert search_results is not None, "Search should return results" |
| 546 | + assert "hits" in search_results, "Search response should contain 'hits'" |
| 547 | + assert "total" in search_results["hits"], "Search hits should contain 'total'" |
| 548 | + |
| 549 | + total_hits = search_results["hits"]["total"] |
| 550 | + if isinstance(total_hits, dict): |
| 551 | + # Elasticsearch 7+ format |
| 552 | + total_count = total_hits["value"] |
| 553 | + else: |
| 554 | + # Elasticsearch 6 format |
| 555 | + total_count = total_hits |
| 556 | + |
| 557 | + assert total_count > 0, f"Expected to find at least 1 log message, but found {total_count}" |
| 558 | + |
| 559 | + # Verify the content of the found document |
| 560 | + hits = search_results["hits"]["hits"] |
| 561 | + assert len(hits) > 0, "Expected at least one hit" |
| 562 | + |
| 563 | + found_document = hits[0]["_source"] |
| 564 | + assert "@timestamp" in found_document, "Expected document to contain '@timestamp' field" |
| 565 | + |
| 566 | + # Get the timestamp from the document |
| 567 | + timestamp_str = found_document["@timestamp"] |
| 568 | + |
| 569 | + # Verify the timestamp format matches ISO 8601 with UTC timezone (Z suffix) |
| 570 | + assert timestamp_str.endswith("Z"), f"Expected timestamp to end with 'Z' (UTC), got: {timestamp_str}" |
| 571 | + |
| 572 | + # Parse the timestamp to verify it's valid |
| 573 | + try: |
| 574 | + parsed_timestamp = datetime.fromisoformat(timestamp_str.replace("Z", "+00:00")) |
| 575 | + except ValueError as e: |
| 576 | + pytest.fail(f"Failed to parse timestamp '{timestamp_str}': {e}") |
| 577 | + |
| 578 | + # Verify the timestamp is timezone-aware (UTC) |
| 579 | + assert parsed_timestamp.tzinfo is not None, "Expected timestamp to be timezone-aware" |
| 580 | + utc_offset = parsed_timestamp.tzinfo.utcoffset(None) |
| 581 | + assert utc_offset is not None and utc_offset.total_seconds() == 0, "Expected timestamp to be in UTC timezone" |
| 582 | + |
| 583 | + # Verify the timestamp is within reasonable bounds (between before and after log time) |
| 584 | + # Allow for some margin due to processing time |
| 585 | + from datetime import timedelta |
| 586 | + |
| 587 | + time_margin = timedelta(seconds=5) # 5 seconds margin |
| 588 | + assert before_log_time - time_margin <= parsed_timestamp <= after_log_time + time_margin, ( |
| 589 | + f"Expected timestamp {parsed_timestamp} to be between {before_log_time} and {after_log_time} " |
| 590 | + f"(with {time_margin} margin)" |
| 591 | + ) |
| 592 | + |
| 593 | + # Verify the timestamp format includes microseconds |
| 594 | + assert "." in timestamp_str, "Expected timestamp to include microseconds" |
| 595 | + assert timestamp_str.count(".") == 1, "Expected timestamp to have exactly one decimal point" |
| 596 | + |
| 597 | + # Verify the format matches the expected pattern: YYYY-MM-DDTHH:MM:SS.ffffffZ |
| 598 | + import re |
| 599 | + |
| 600 | + iso_pattern = r"^\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}\.\d{6}Z$" |
| 601 | + assert re.match(iso_pattern, timestamp_str), f"Expected timestamp to match ISO 8601 pattern, got: {timestamp_str}" |
| 602 | + |
| 603 | + print(f"Successfully verified timestamp format: {timestamp_str}") |
| 604 | + print(f"Parsed timestamp: {parsed_timestamp} (UTC)") |
| 605 | + print(f"Timestamp is within expected time range: {before_log_time} <= {parsed_timestamp} <= {after_log_time}") |
0 commit comments