Skip to content
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.

Sign up for GitHub

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

feat: Support search logs by timestamp for structured and unstructured logs. #42

Open
wants to merge 33 commits into
base: main
Choose a base branch
from
Open

feat: Support search logs by timestamp for structured and unstructured logs. #42

Show file tree
Hide file tree
Changes from 32 commits
Commits
Show all changes
33 commits
Select commit Hold shift + click to select a range
ea23947
search timestamp works for unstructured logs
Henry8192 Nov 19, 2024
7edaa48
Merge branch 'y-scope:main' into search-timestamp
Henry8192 Dec 16, 2024
7481573
Merge branch 'main' into search-timestamp
Henry8192 Dec 18, 2024
3ee05a2
fix lint
Henry8192 Dec 19, 2024
f1a71a1
implement structured logs search by timestamp
Henry8192 Dec 22, 2024
5263385
Merge branch 'main' into search-timestamp
Henry8192 Dec 22, 2024
c423ec5
address partial changes from review
Henry8192 Dec 27, 2024
467e998
snapshot: get_timestamp seems to be undefined for std::upper_bound
Henry8192 Dec 30, 2024
c66cb80
fix lint
Henry8192 Dec 30, 2024
89338f7
pass in log_events instead of iterators to generic_get_log_event_inde…
Henry8192 Jan 2, 2025
a99ec2a
switch back to std::upper_bound because std::ranges::upper_bound is n…
Henry8192 Jan 6, 2025
9ec039f
fix lint
Henry8192 Jan 6, 2025
4f125b8
change generic_get_log_event_index_by_timestamp behavior: only return…
Henry8192 Jan 6, 2025
5221588
edit docstring for get_log_event_index_by_timestamp
Henry8192 Jan 6, 2025
abeb4f8
fix lint
Henry8192 Jan 6, 2025
6647fbd
Apply suggestions from code review
Henry8192 Jan 8, 2025
046191e
use concept to shorten function definition; minor change to generic_g…
Henry8192 Jan 8, 2025
4c7386d
Merge branch 'main' into search-timestamp
Henry8192 Jan 9, 2025
c400361
fix lint & syntax
Henry8192 Jan 9, 2025
ca4a616
rename get_log_event_index_by_timestamp to get_log_event_idx_by_times…
Henry8192 Jan 9, 2025
9443ba3
revert comments and plan to fix in the next pr
Henry8192 Jan 10, 2025
db60efd
add back the missing space
Henry8192 Jan 10, 2025
0e3e21b
revert decode_range (without creating concept)
Henry8192 Jan 10, 2025
412b96e
address changes from Marco's review
Henry8192 Jan 13, 2025
54c7df1
remove unnecessary require statement for get_log_event_idx_by_timestamp
Henry8192 Jan 13, 2025
eff1849
address the rest of the comments
Henry8192 Jan 13, 2025
00f89d4
address code review changes
Henry8192 Jan 14, 2025
122f1cf
fix lint
Henry8192 Jan 15, 2025
f4a0207
resolve the rest of the conflicts
Henry8192 Jan 29, 2025
46fa81f
revert the CMakeList Change
Henry8192 Jan 30, 2025
8c8c42e
address kirk's comments in the code review
Henry8192 Feb 1, 2025
a984d7b
revert function name to find_nearest_log_event_by_timestamp
Henry8192 Feb 3, 2025
4788157
amend find_nearest_log_event_by_timestamp's comments, warning this fu…
Henry8192 Feb 4, 2025
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
7 changes: 6 additions & 1 deletion src/clp_ffi_js/ir/StreamReader.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -129,6 +129,7 @@ EMSCRIPTEN_BINDINGS(ClpStreamReader) {
"Array<[string, bigint, number, number]>"
);
emscripten::register_type<clp_ffi_js::ir::FilteredLogEventMapTsType>("number[] | null");
emscripten::register_type<clp_ffi_js::ir::NullableLogEventIdx>("number | null");
emscripten::class_<clp_ffi_js::ir::StreamReader>("ClpStreamReader")
.constructor(
&clp_ffi_js::ir::StreamReader::create,
Expand All @@ -145,7 +146,11 @@ EMSCRIPTEN_BINDINGS(ClpStreamReader) {
)
.function("filterLogEvents", &clp_ffi_js::ir::StreamReader::filter_log_events)
.function("deserializeStream", &clp_ffi_js::ir::StreamReader::deserialize_stream)
.function("decodeRange", &clp_ffi_js::ir::StreamReader::decode_range);
.function("decodeRange", &clp_ffi_js::ir::StreamReader::decode_range)
.function(
"findNearestLogEventByTimestamp",
&clp_ffi_js::ir::StreamReader::find_nearest_log_event_by_timestamp
);
}
} // namespace

Expand Down
62 changes: 62 additions & 0 deletions src/clp_ffi_js/ir/StreamReader.hpp
View file
Open in desktop
Henry8192 marked this conversation as resolved.
Show resolved Hide resolved
Original file line number Diff line number Diff line change
Expand Up @@ -11,6 +11,7 @@
#include <type_traits>
#include <vector>

#include <clp/ir/types.hpp>
#include <clp/streaming_compression/zstd/Decompressor.hpp>
#include <clp/type_utils.hpp>
#include <emscripten/em_asm.h>
Expand All @@ -29,6 +30,7 @@ EMSCRIPTEN_DECLARE_VAL_TYPE(ReaderOptions);
// JS types used as outputs
EMSCRIPTEN_DECLARE_VAL_TYPE(DecodedResultsTsType);
EMSCRIPTEN_DECLARE_VAL_TYPE(FilteredLogEventMapTsType);
EMSCRIPTEN_DECLARE_VAL_TYPE(NullableLogEventIdx);

enum class StreamType : uint8_t {
Structured,
Expand Down Expand Up @@ -124,6 +126,24 @@ class StreamReader {
[[nodiscard]] virtual auto decode_range(size_t begin_idx, size_t end_idx, bool use_filter) const
-> DecodedResultsTsType = 0;

/**
Henry8192 marked this conversation as resolved.
Show resolved Hide resolved
* Finds the log event, L, where if we assume:
*
* - the collection of log events is sorted in ascending timestamp order;
* - and we insert a marker log event, M, with timestamp `target_ts` into the collection (if log
* events with timestamp `target_ts` already exist in the collection, M should be inserted
* after them).
*
* L is the event just before M, if M is not the first event in the collection; otherwise L is
* the event just after M.
*
* @param target_ts
* @return The index of the log event L.
*/
[[nodiscard]] virtual auto find_nearest_log_event_by_timestamp(
clp::ir::epoch_time_ms_t target_ts
) -> NullableLogEventIdx = 0;

protected:
explicit StreamReader() = default;

Expand Down Expand Up @@ -172,6 +192,20 @@ class StreamReader {
LogLevelFilterTsType const& log_level_filter,
LogEvents<LogEvent> const& log_events
) -> void;

/**
* Templated implementation of `find_nearest_log_event_by_timestamp`.
*
* @tparam LogEvent
* @param log_events
* @param target_ts
* @return See `find_nearest_log_event_by_timestamp`.
*/
template <typename LogEvent>
auto generic_find_nearest_log_event_by_timestamp(
LogEvents<LogEvent> const& log_events,
clp::ir::epoch_time_ms_t target_ts
) -> NullableLogEventIdx;
};

template <typename LogEvent, typename ToStringFunc>
Expand Down Expand Up @@ -258,6 +292,34 @@ auto StreamReader::generic_filter_log_events(
}
}
}

template <typename LogEvent>
auto StreamReader::generic_find_nearest_log_event_by_timestamp(
LogEvents<LogEvent> const& log_events,
clp::ir::epoch_time_ms_t target_ts
) -> NullableLogEventIdx {
if (log_events.empty()) {
return NullableLogEventIdx{emscripten::val::null()};
}
Henry8192 marked this conversation as resolved.
Show resolved Hide resolved

// Find the log event whose timestamp is just after `target_ts`
auto first_greater_it{std::upper_bound(
Copy link
Member

Choose a reason for hiding this comment

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

std::upper_bound assumes the range is sorted, right? What would happen if the log events aren't in ascending timestamp order? It's technically not impossible and we have seen log files where that's true.

Copy link
Collaborator Author

Choose a reason for hiding this comment

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

@junhaoliao iirc, I was told to assume the log events are in accending order. If that's not the case, this whole search function won't work.

If that's not the case, we have to sort all of the log events, cuz' that's the only way to fully garantee all log events are sorted. And we (might?) also need a map to remember their original location.

Copy link
Member

Choose a reason for hiding this comment

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

Since the case with out of order timestamps is rare (as far as we know), we could maybe do something like:

  • When decoding the file, keep track of whether the timestamp of two consecutive log events are out of order and if so, set a flag and display a warning to the user that the file contains out of order timestamps and so timestamp-related searches may not function correctly (since two log events with the same timestamp may exist at completely different positions in the log file).
  • If that flag is set, we use a brute-force implementation of find_nearest_log_event_by_timestamp. Otherwise, we use the implementation you have here.

Copy link
Collaborator Author

Choose a reason for hiding this comment

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

  • When decoding the file, keep track of whether the timestamp of two consecutive log events are out of order
    "keep track of" means we are basically iterating the log events during the decode right?

if that's the case, can we divide the log events up to chunks using these timestamp outliers, perform searches in the proper chunk, and finally iterate those outliers?

Copy link
Member

Choose a reason for hiding this comment

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

Would that be straightforward to do given that the log events collection changes based on the active filter? If not, then given how rare the case is (as far as we know), I'm not sure the extra code complexity is worth it.

Copy link
Collaborator Author

Choose a reason for hiding this comment

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

In an offline discussion with @junhaoliao, we reach to an agreement that we can doc the assumption, and neglact this corner case.

By neglacting this corner case, we can save plenty of resource from verifying log events are in chronological order.

Henry8192 marked this conversation as resolved.
Show resolved Hide resolved
Henry8192 marked this conversation as resolved.
Show resolved Hide resolved
log_events.begin(),
log_events.end(),
target_ts,
[](clp::ir::epoch_time_ms_t ts, LogEventWithFilterData<LogEvent> const& log_event) {
return ts < log_event.get_timestamp();
}
)};

if (first_greater_it == log_events.begin()) {
return NullableLogEventIdx{emscripten::val(0)};
}

auto const first_greater_idx{std::distance(log_events.begin(), first_greater_it)};

return NullableLogEventIdx{emscripten::val(first_greater_idx - 1)};
}
Comment on lines +296 to +322
Copy link

Choose a reason for hiding this comment

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

💡 Codebase verification

Attention: Log events ordering may not be enforced.

Our investigation shows that the implementation of generic_find_nearest_log_event_by_timestamp relies on log events being in ascending timestamp order, yet searches for sorting or ordering logic (e.g. explicit calls to std::sort or other ordering mechanisms) produced no evidence to enforce this order during deserialization or insertion. This could potentially lead to incorrect log event lookups if the input sequence isn’t already sorted.

  • The log events appear to be added via methods like emplace_back without explicit ordering.
  • No ordering logic (e.g. sorting function calls) was identified to confirm that the events are sorted as required.
🔗 Analysis chain

Verify timestamp ordering assumption.

The implementation assumes log events are sorted by timestamp in ascending order. This assumption should be verified as log files might not always maintain this order.

Run this script to check if timestamps are always in ascending order:

🏁 Scripts executed

The following scripts were executed for the analysis:

Script:

#!/bin/bash
# Description: Check if timestamps are in ascending order during log event deserialization
# Expected: Find all places where timestamps are added to log events

# Search for timestamp assignments during deserialization
ast-grep --pattern $'deserialize_log_event() {
  $$$
  get_timestamp()
  $$$
}'

# Search for places where log events are added to collections
rg -A 5 "emplace_back.*LogEvent"

Length of output: 115

Script:

#!/bin/bash
# Investigate ordering logic for log events in the codebase

# 1. Search for std::sort invocations that might enforce timestamp ordering
rg -n "std::sort\s*\(.*get_timestamp" --color=always

# 2. Locate deserialization functions potentially responsible for creating or ordering log events
rg -n "deserialize_log_event\s*\(" --color=always

# 3. Find where log events are inserted into collections (e.g. using emplace_back) to inspect their ordering
rg -n "emplace_back\s*\(.*LogEvent" --color=always

# 4. Additionally, search for any comparison operators or functions comparing timestamps
rg -n "get_timestamp\s*\(" --color=always

Length of output: 1721

} // namespace clp_ffi_js::ir

#endif // CLP_FFI_JS_IR_STREAMREADER_HPP
7 changes: 7 additions & 0 deletions src/clp_ffi_js/ir/StructuredIrStreamReader.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -11,6 +11,7 @@
#include <clp/Array.hpp>
#include <clp/ErrorCode.hpp>
#include <clp/ffi/ir_stream/Deserializer.hpp>
#include <clp/ir/types.hpp>
#include <clp/TraceableException.hpp>
#include <emscripten/val.h>
#include <spdlog/spdlog.h>
Expand Down Expand Up @@ -147,6 +148,12 @@ auto StructuredIrStreamReader::decode_range(size_t begin_idx, size_t end_idx, bo
);
}

auto StructuredIrStreamReader::find_nearest_log_event_by_timestamp(
clp::ir::epoch_time_ms_t const target_ts
) -> NullableLogEventIdx {
return generic_find_nearest_log_event_by_timestamp(*m_deserialized_log_events, target_ts);
}

StructuredIrStreamReader::StructuredIrStreamReader(
StreamReaderDataContext<StructuredIrDeserializer>&& stream_reader_data_context,
std::shared_ptr<StructuredLogEvents> deserialized_log_events
Expand Down
4 changes: 4 additions & 0 deletions src/clp_ffi_js/ir/StructuredIrStreamReader.hpp
View file
Open in desktop
Henry8192 marked this conversation as resolved.
Show resolved Hide resolved
Original file line number Diff line number Diff line change
Expand Up @@ -8,6 +8,7 @@
#include <clp/Array.hpp>
#include <clp/ffi/ir_stream/Deserializer.hpp>
#include <clp/ffi/SchemaTree.hpp>
#include <clp/ir/types.hpp>
#include <emscripten/val.h>

#include <clp_ffi_js/ir/LogEventWithFilterData.hpp>
Expand Down Expand Up @@ -74,6 +75,9 @@ class StructuredIrStreamReader : public StreamReader {
[[nodiscard]] auto decode_range(size_t begin_idx, size_t end_idx, bool use_filter) const
-> DecodedResultsTsType override;

[[nodiscard]] auto find_nearest_log_event_by_timestamp(clp::ir::epoch_time_ms_t target_ts
) -> NullableLogEventIdx override;

private:
// Constructor
explicit StructuredIrStreamReader(
Expand Down
6 changes: 6 additions & 0 deletions src/clp_ffi_js/ir/UnstructuredIrStreamReader.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -158,6 +158,12 @@ auto UnstructuredIrStreamReader::decode_range(size_t begin_idx, size_t end_idx,
);
}

auto UnstructuredIrStreamReader::find_nearest_log_event_by_timestamp(
clp::ir::epoch_time_ms_t const target_ts
) -> NullableLogEventIdx {
return generic_find_nearest_log_event_by_timestamp(m_encoded_log_events, target_ts);
}

UnstructuredIrStreamReader::UnstructuredIrStreamReader(
StreamReaderDataContext<UnstructuredIrDeserializer>&& stream_reader_data_context
)
Expand Down
3 changes: 3 additions & 0 deletions src/clp_ffi_js/ir/UnstructuredIrStreamReader.hpp
View file
Open in desktop
Henry8192 marked this conversation as resolved.
Show resolved Hide resolved
Original file line number Diff line number Diff line change
Expand Up @@ -71,6 +71,9 @@ class UnstructuredIrStreamReader : public StreamReader {
[[nodiscard]] auto decode_range(size_t begin_idx, size_t end_idx, bool use_filter) const
-> DecodedResultsTsType override;

[[nodiscard]] auto find_nearest_log_event_by_timestamp(clp::ir::epoch_time_ms_t target_ts
) -> NullableLogEventIdx override;

private:
// Constructor
explicit UnstructuredIrStreamReader(
Expand Down
Loading