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
|
# 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
import pw_log_tokenized
from pw_log.proto import log_pb2
from pw_rpc import callback_client, console_tools
from pw_status import Status
from pw_tokenizer.detokenize import Detokenizer
from pw_tokenizer.proto import decode_optionally_tokenized
# 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[Detokenizer],
timestamp_decoder: Optional[Callable[[int], str]],
rpc_timeout_s=5):
self.channel_id = channel_id
self.protos = proto_library
self.detokenizer = detokenizer
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=rpc_timeout_s,
default_stream_timeout_s=None,
)
self.client = HdlcRpcClient(
read,
self.protos,
default_channels(write),
lambda data: self.logger.info("%s", str(data)),
client_impl=callback_client_impl)
# 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 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):
message = f'Dropped {drop_count} log'
if drop_count > 1:
message += 's'
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)
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 = pw_log_tokenized.FormatStringWithMetadata(message)
# Handle dropped count.
if log_proto.dropped:
self._handle_log_drop_count(log_proto.dropped)
return
self._emit_device_log(level, '', decoded_timestamp, log.module,
log.message, **dict(log.fields))
def _emit_device_log(self, level: int, source_name: str, timestamp: str,
module_name: str, message: str, **metadata_fields):
# Fields used for console table view
fields = metadata_fields
fields['source_name'] = source_name
fields['timestamp'] = timestamp
fields['msg'] = message
fields['module'] = module_name
# Format used for file or stdout logging.
self.logger.log(level,
'[%s] %s %s%s',
source_name,
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]
|
