pw_system/py/pw_system/device.py

# 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

        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 _log_entries_proto_parser(self, log_entries_proto: log_pb2.LogEntries):
        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)
            decoded_message = log.message

            # Handle dropped count.
            if log_proto.dropped:
                level = logging.WARNING
                decoded_timestamp = ''
                decoded_message = f'Dropped {log_proto.dropped} log'
                if log_proto.dropped > 1:
                    decoded_message += 's'

            self._emit_device_log(level, '', decoded_timestamp, log.module,
                                  decoded_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]