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

Improve request tracking in log processor #596

Merged
merged 6 commits into from
Mar 29, 2018
Merged

Improve request tracking in log processor #596

Show file tree
Hide file tree
Changes from 4 commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
ff3edff
Log processor: moved request tracking to python, improved usability a…
Mar 28, 2018
08dc379
Log processor: streamlined tags/attributes workflow, updated doc
Mar 28, 2018
2ef520e
Log processor: added example for tracking single request
Mar 28, 2018
c6b5c87
Log processor: improved requests tracking, fixed bugs
Mar 28, 2018
1df990a
Log processor: simplify request tracking example
Mar 28, 2018
1e785dd
Log processor: implement processing gzipped logs
Mar 28, 2018
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
58 changes: 40 additions & 18 deletions scripts/process_logs/README.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -71,6 +71,7 @@ Contains dictionary of output log files, each with following options:
- `<level>`: log level (DEBUG, INFO, WARNING, etc)
- `<source>`: source file which emitted message
- `<func>`: function which emitted message
- `<body>`: message body
- `<user attr>`: any user-defined attribute, explained later in
*chains* section

Expand All @@ -97,6 +98,23 @@ of matcher, value is parameter. For submatchers that don't have parameters
(for example, other custom matchers) value should be omitted. Custom matcher
matches message if any of its sub-matchers matches message.

Matcher name resolution rules are:
- check if this is any of builtin matchers (listed below)
- check if this is a custom matcher
- consider this custom attribute matcher

Attribute matchers check if message has given attribute, and, when value is
provided, if attribute contains given value. For example, matcher
```yaml
- is_request:
```
checks that message has attribute `is_request`, and matcher
```yaml
- reqId: 42
```
checks that message has attribute `reqId` containing value `42`


#### Builtin matchers
- `timestamp`: checks if message timestamp is within defined limits.
Parameter for this matcher is dictionary with `min` and `max` values
Expand Down Expand Up @@ -137,17 +155,6 @@ matches message if any of its sub-matchers matches message.
- `node`: message is actually from node, not replica
- `master`: message is from master replica or from node
- `backup`: message is from any of backup replicas
- `tag`: checks if message is tagged with specified tag (tagging explained
later in *chains* section), for example:
```yaml
- tag: NETWORK
```
- `attribute`: check if message has custom attribute (explained later in
*chains* section) with matching name and value, specified as a dictionary
with single key-value pair, for example:
```yaml
- attribute: {viewNo: 2}
```
- `any`: check if message matches any submatcher, specified as a list:
```yaml
- any:
Expand Down Expand Up @@ -262,24 +269,39 @@ commands.
- `and`: perform action when message is matched
- `return`: action to perform is to return from current chain to calling one
- `drop`: action to perform is to drop message altogether
- `track_requests`: track requests, adding multiple attributes to relevant
messages:
- reqId: request identifier
- TODO: list other attibutes
- `tag`: optionally checks if message matches some regex pattern and sets
custom tags and/or attributes on it. Parameter for this command is dictionary
with following keys:
- `pattern`: pattern to match message body
- `tags`: list of tags to add to message on match
- `attributes`: dictionary of custom attributes to add to message on match,
with keys being attribute names and values index of matching regex group.
with keys being attribute names and values being one of:
- empty: indicating tag-like attribute which doesn't have any value
- arbitrary string: sets this string as attribute value
- `group <n>`: sets matching regex group as attribute value
For example:
```yaml
- tag:
pattern: sending (\w+), viewNo: (\d+)
tags: [SEND]
attributes:
message_type: 1
view_no: 2
is_message:
message_action: send
message_type: group 1
view_no: group 2
```
will add following attributes to messages containing
`sending COMMIT, viewNo: 23`:
```
is_message: []
message_action: send
message_type: COMMIT
view_no: 23
```
will add tag `SEND` to messages containing `sending COMMIT, viewNo: 23`,
and adds custom attributes `message_type: COMMIT` and `view_no: 23`.
It's possible for multiple tagger to write to same attribute multiple
times, in this case it will contain all written values.

## Standard (in process_logs.yml) matchers and chains

Expand Down
8 changes: 4 additions & 4 deletions scripts/process_logs/example_network.yml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -9,7 +9,7 @@ input_logs: # List of input logs

chains: # List of processing chains
main: # Main processing chain
- match or drop: [network_message] # Drop everything except network-related messages
- match or drop: network_message # Drop everything except network-related messages
- log_total: # Call chain log_total
- log_ping_pong: # Call chain log_ping_pong
- log_disconnect: # Call chain log_disconnect
Expand All @@ -20,12 +20,12 @@ chains: # List of processing chains
# By default return message to calling chain

log_ping_pong:
- match: [network_ping_pong] # Return unless message is network ping pong
- match: network_ping_pong # Return unless message is network ping pong
- log time: {general: ping_pong} # Add message to general-ping_pong timelog sink
- drop: # Drop message, since we'll no longer need it

log_disconnect:
- match: [network_disconnect] # Return unless message is network disconnect
- match: network_disconnect # Return unless message is network disconnect
- log time: {general: disconnect} # Add message to general-disconnect timelog sink
- log time: {alarms: disconnect} # Add message to alarms-disconnect timelog sink
- drop: # Drop message, since we'll no longer need it
Expand All @@ -34,7 +34,7 @@ outputs:
logs: # List of output log sinks
network: # Network log sink
filename: output.log # Filename where to put messages
pattern: <timestamp> | <node> | <message> # Message format
pattern: <timestamp> | <node> | <body> # Message format

timelogs: # List of timelog
general: # General timelog
Expand Down
2 changes: 1 addition & 1 deletion scripts/process_logs/example_process.yml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -31,7 +31,7 @@ outputs:
logs:
output:
filename: output.log
pattern: <timestamp> | <node> <replica> | <source> | <func> | <message>
pattern: <timestamp> | <node> <replica> | <source> | <func> | <body>

timelogs:
monitoring:
Expand Down
13 changes: 6 additions & 7 deletions scripts/process_logs/example_track_req.yml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -10,26 +10,26 @@ input_logs: # List of input logs
chains: # List of processing chains
main: # Main processing chain
- match: [replica: master]
- tag_requests:
- match: [tag: REQUEST]
- track_requests:
- match: request
- log line: output
- stat_received:
- stat_already_processed:
- stat_ordered:

stat_received:
- match: [tag: RECEIVED]
- match: [request: received]
- log count: { stats: received }
- log time: { stats: received }
- drop:

stat_already_processed:
- match: [tag: ALREADY_PROCESSED]
- match: [request: already_processed]
- log count: { stats: already_processed }
- drop:

stat_ordered:
- match: [tag: ORDERED]
- match: [request: ordered]
- log count: { stats: ordered }
- log time: { stats: ordered }
- drop:
Expand All @@ -47,5 +47,4 @@ outputs:

counters:
stats:
format: |
<node> requests: <received> received, <already_processed> already_processed, <ordered> ordered
format: "<node> requests: <received>/<ordered> received/ordered, <already_processed> already_processed"
19 changes: 19 additions & 0 deletions scripts/process_logs/example_track_single_req.yml
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,19 @@

input_logs: # List of input logs
- path: . # Where to look for log files
recursive: yes # Whether to descend into subdirectories recursively
pattern: (Node\d+)\.log # Log file regex pattern to look for
node_group: 1 # Group number that matches node identifier
only_timestamped: yes # Whether to discard non-timestamped lines


chains: # List of processing chains
main: # Main processing chain
- track_requests:
- match: [reqId: 1521518081149711394]
- log line: output

outputs:
logs: # List of output log sinks
output: # View change log sink
filename: output_<replica>.log # Filename where to put messages
8 changes: 4 additions & 4 deletions scripts/process_logs/example_view_change.yml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -17,13 +17,13 @@ chains: # List of processing chains
- log_view_change_done: # Call chain log_view_change_done

log_view_change_start:
- match: [view_change_start] # Return unless message is view change start
- match: view_change_start # Return unless message is view change start
- log line: view_change_start_done # Save message to view_change_start_done log sink
- log time: {view_change: start} # Add message to view_change-start timelog sink
- drop: # Drop message, since we'll no longer need it

log_view_change_done:
- match: [view_change_done] # Return unless message is view change done
- match: view_change_done # Return unless message is view change done
- log line: view_change_start_done # Save message to view_change_start_done log sink
- log time: {view_change: done} # Add message to view_change-done timelog sink
- drop: # Drop message, since we'll no longer need it
Expand All @@ -32,10 +32,10 @@ outputs:
logs: # List of output log sinks
view_change: # View change log sink
filename: view_change.log # Filename where to put messages
pattern: <timestamp> | <node> | <message> # Message format
pattern: <timestamp> | <node> | <body> # Message format
view_change_start_done: # View change start/done log sink
filename: view_change_sd_<replica>.log # Filename where to put messages
pattern: <timestamp> | <node> | <message> # Message format
pattern: <timestamp> | <node> | <body> # Message format

timelogs: # List of timelog
view_change: # View changes timelog
Expand Down
Loading