1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
|
# Copyright 2021 The Pigweed Authors
#
# Licensed under the Apache License, Version 2.0 (the "License"); you may not
# use this file except in compliance with the License. You may obtain a copy of
# the License at
#
# https://www.apache.org/licenses/LICENSE-2.0
#
# Unless required by applicable law or agreed to in writing, software
# distributed under the License is distributed on an "AS IS" BASIS, 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.
"""Device classes to interact with targets via RPC."""
import datetime
import logging
from pathlib import Path
from types import ModuleType
from typing import Any, Callable, List, Union, Optional
from pw_hdlc.rpc import HdlcRpcClient, default_channels
from pw_log_tokenized import FormatStringWithMetadata
from pw_log.proto import log_pb2
from pw_metric import metric_parser
from pw_rpc import callback_client, console_tools
from pw_status import Status
from pw_thread.thread_analyzer import ThreadSnapshotAnalyzer
from pw_thread_protos import thread_pb2
from pw_tokenizer import detokenize
from pw_tokenizer.proto import decode_optionally_tokenized
from pw_unit_test.rpc import run_tests as pw_unit_test_run_tests
# Internal log for troubleshooting this tool (the console).
_LOG = logging.getLogger('tools')
DEFAULT_DEVICE_LOGGER = logging.getLogger('rpc_device')
class Device:
"""Represents an RPC Client for a device running a Pigweed target.
The target must have and RPC support, RPC logging.
Note: use this class as a base for specialized device representations.
"""
def __init__(
self,
channel_id: int,
read,
write,
proto_library: List[Union[ModuleType, Path]],
detokenizer: Optional[detokenize.Detokenizer],
timestamp_decoder: Optional[Callable[[int], str]],
rpc_timeout_s: float = 5,
use_rpc_logging: bool = True,
):
self.channel_id = channel_id
self.protos = proto_library
self.detokenizer = detokenizer
self.rpc_timeout_s = rpc_timeout_s
self.logger = DEFAULT_DEVICE_LOGGER
self.logger.setLevel(logging.DEBUG) # Allow all device logs through.
self.timestamp_decoder = timestamp_decoder
self._expected_log_sequence_id = 0
callback_client_impl = callback_client.Impl(
default_unary_timeout_s=self.rpc_timeout_s,
default_stream_timeout_s=None,
)
def detokenize_and_log_output(data: bytes, _detokenizer=None):
log_messages = data.decode(
encoding='utf-8', errors='surrogateescape'
)
if self.detokenizer:
log_messages = decode_optionally_tokenized(
self.detokenizer, data
)
for line in log_messages.splitlines():
self.logger.info(line)
self.client = HdlcRpcClient(
read,
self.protos,
default_channels(write),
detokenize_and_log_output,
client_impl=callback_client_impl,
)
if use_rpc_logging:
# Start listening to logs as soon as possible.
self.listen_to_log_stream()
def info(self) -> console_tools.ClientInfo:
return console_tools.ClientInfo('device', self.rpcs, self.client.client)
@property
def rpcs(self) -> Any:
"""Returns an object for accessing services on the specified channel."""
return next(iter(self.client.client.channels())).rpcs
def run_tests(self, timeout_s: Optional[float] = 5) -> bool:
"""Runs the unit tests on this device."""
return pw_unit_test_run_tests(self.rpcs, timeout_s=timeout_s)
def listen_to_log_stream(self):
"""Opens a log RPC for the device's unrequested log stream.
The RPCs remain open until the server cancels or closes them, either
with a response or error packet.
"""
self.rpcs.pw.log.Logs.Listen.open(
on_next=lambda _, log_entries_proto: self._log_entries_proto_parser(
log_entries_proto
),
on_completed=lambda _, status: _LOG.info(
'Log stream completed with status: %s', status
),
on_error=lambda _, error: self._handle_log_stream_error(error),
)
def _handle_log_stream_error(self, error: Status):
"""Resets the log stream RPC on error to avoid losing logs."""
_LOG.error('Log stream error: %s', error)
# Only re-request logs if the RPC was not cancelled by the client.
if error != Status.CANCELLED:
self.listen_to_log_stream()
def _handle_log_drop_count(self, drop_count: int, reason: str):
log_text = 'log' if drop_count == 1 else 'logs'
message = f'Dropped {drop_count} {log_text} due to {reason}'
self._emit_device_log(logging.WARNING, '', '', message)
def _check_for_dropped_logs(self, log_entries_proto: log_pb2.LogEntries):
# Count log messages received that don't use the dropped field.
messages_received = sum(
1 if not log_proto.dropped else 0
for log_proto in log_entries_proto.entries
)
dropped_log_count = (
log_entries_proto.first_entry_sequence_id
- self._expected_log_sequence_id
)
self._expected_log_sequence_id = (
log_entries_proto.first_entry_sequence_id + messages_received
)
if dropped_log_count > 0:
self._handle_log_drop_count(dropped_log_count, 'loss at transport')
elif dropped_log_count < 0:
_LOG.error('Log sequence ID is smaller than expected')
def _log_entries_proto_parser(self, log_entries_proto: log_pb2.LogEntries):
self._check_for_dropped_logs(log_entries_proto)
for log_proto in log_entries_proto.entries:
decoded_timestamp = self.decode_timestamp(log_proto.timestamp)
# Parse level and convert to logging module level number.
level = (log_proto.line_level & 0x7) * 10
if self.detokenizer:
message = str(
decode_optionally_tokenized(
self.detokenizer, log_proto.message
)
)
else:
message = log_proto.message.decode('utf-8')
log = FormatStringWithMetadata(message)
# Handle dropped count.
if log_proto.dropped:
drop_reason = (
log_proto.message.decode('utf-8').lower()
if log_proto.message
else 'enqueue failure on device'
)
self._handle_log_drop_count(log_proto.dropped, drop_reason)
continue
self._emit_device_log(
level,
decoded_timestamp,
log.module,
log.message,
**dict(log.fields),
)
def _emit_device_log(
self,
level: int,
timestamp: str,
module_name: str,
message: str,
**metadata_fields,
):
# Fields used for console table view
fields = metadata_fields
fields['timestamp'] = timestamp
fields['msg'] = message
fields['module'] = module_name
# Format used for file or stdout logging.
self.logger.log(
level,
'%s %s%s',
timestamp,
f'{module_name} '.lstrip(),
message,
extra=dict(extra_metadata_fields=fields),
)
def decode_timestamp(self, timestamp: int) -> str:
"""Decodes timestamp to a human-readable value.
Defaults to interpreting the input timestamp as nanoseconds since boot.
Devices can override this to match their timestamp units.
"""
if self.timestamp_decoder:
return self.timestamp_decoder(timestamp)
return str(datetime.timedelta(seconds=timestamp / 1e9))[:-3]
def get_and_log_metrics(self) -> dict:
"""Retrieves the parsed metrics and logs them to the console."""
metrics = metric_parser.parse_metrics(
self.rpcs, self.detokenizer, self.rpc_timeout_s
)
def print_metrics(metrics, path):
"""Traverses dictionaries, until a non-dict value is reached."""
for path_name, metric in metrics.items():
if isinstance(metric, dict):
print_metrics(metric, path + '/' + path_name)
else:
_LOG.info('%s/%s: %s', path, path_name, str(metric))
print_metrics(metrics, '')
return metrics
def snapshot_peak_stack_usage(self, thread_name: Optional[str] = None):
_, rsp = self.rpcs.pw.thread.ThreadSnapshotService.GetPeakStackUsage(
name=thread_name
)
thread_info = thread_pb2.SnapshotThreadInfo()
for thread_info_block in rsp:
for thread in thread_info_block.threads:
thread_info.threads.append(thread)
for line in str(ThreadSnapshotAnalyzer(thread_info)).splitlines():
_LOG.info('%s', line)
|
