1#!/usr/bin/env python3 2# 3# Copyright 2018 - The Android Open Source Project 4# 5# Licensed under the Apache License, Version 2.0 (the "License"); 6# you may not use this file except in compliance with the License. 7# You may obtain a copy of the License at 8# 9# http://www.apache.org/licenses/LICENSE-2.0 10# 11# Unless required by applicable law or agreed to in writing, software 12# distributed under the License is distributed on an "AS IS" BASIS, 13# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 14# See the License for the specific language governing permissions and 15# limitations under the License. 16 17import backoff 18import json 19import logging 20import platform 21import os 22import random 23import re 24import requests 25import subprocess 26import socket 27import time 28 29from acts import context 30from acts import logger as acts_logger 31from acts import utils 32from acts import signals 33 34from acts.controllers import pdu 35 36from acts.controllers.fuchsia_lib.audio_lib import FuchsiaAudioLib 37from acts.controllers.fuchsia_lib.backlight_lib import FuchsiaBacklightLib 38from acts.controllers.fuchsia_lib.bt.avdtp_lib import FuchsiaAvdtpLib 39from acts.controllers.fuchsia_lib.bt.hfp_lib import FuchsiaHfpLib 40from acts.controllers.fuchsia_lib.light_lib import FuchsiaLightLib 41 42from acts.controllers.fuchsia_lib.basemgr_lib import FuchsiaBasemgrLib 43from acts.controllers.fuchsia_lib.bt.ble_lib import FuchsiaBleLib 44from acts.controllers.fuchsia_lib.bt.bts_lib import FuchsiaBtsLib 45from acts.controllers.fuchsia_lib.bt.gattc_lib import FuchsiaGattcLib 46from acts.controllers.fuchsia_lib.bt.gatts_lib import FuchsiaGattsLib 47from acts.controllers.fuchsia_lib.bt.sdp_lib import FuchsiaProfileServerLib 48from acts.controllers.fuchsia_lib.gpio_lib import FuchsiaGpioLib 49from acts.controllers.fuchsia_lib.hardware_power_statecontrol_lib import FuchsiaHardwarePowerStatecontrolLib 50from acts.controllers.fuchsia_lib.hwinfo_lib import FuchsiaHwinfoLib 51from acts.controllers.fuchsia_lib.i2c_lib import FuchsiaI2cLib 52from acts.controllers.fuchsia_lib.input_report_lib import FuchsiaInputReportLib 53from acts.controllers.fuchsia_lib.kernel_lib import FuchsiaKernelLib 54from acts.controllers.fuchsia_lib.location.regulatory_region_lib import FuchsiaRegulatoryRegionLib 55from acts.controllers.fuchsia_lib.logging_lib import FuchsiaLoggingLib 56from acts.controllers.fuchsia_lib.netstack.netstack_lib import FuchsiaNetstackLib 57from acts.controllers.fuchsia_lib.ram_lib import FuchsiaRamLib 58from acts.controllers.fuchsia_lib.syslog_lib import FuchsiaSyslogError 59from acts.controllers.fuchsia_lib.syslog_lib import start_syslog 60from acts.controllers.fuchsia_lib.sysinfo_lib import FuchsiaSysInfoLib 61from acts.controllers.fuchsia_lib.utils_lib import create_ssh_connection 62from acts.controllers.fuchsia_lib.utils_lib import SshResults 63from acts.controllers.fuchsia_lib.wlan_deprecated_configuration_lib import FuchsiaWlanDeprecatedConfigurationLib 64from acts.controllers.fuchsia_lib.wlan_lib import FuchsiaWlanLib 65from acts.controllers.fuchsia_lib.wlan_ap_policy_lib import FuchsiaWlanApPolicyLib 66from acts.controllers.fuchsia_lib.wlan_policy_lib import FuchsiaWlanPolicyLib 67from acts.controllers.fuchsia_lib.lib_controllers.wlan_controller import WlanController 68from acts.controllers.fuchsia_lib.lib_controllers.wlan_policy_controller import WlanPolicyController 69from acts.libs.proc import job 70from acts.utils import get_fuchsia_mdns_ipv6_address 71 72MOBLY_CONTROLLER_CONFIG_NAME = "FuchsiaDevice" 73ACTS_CONTROLLER_REFERENCE_NAME = "fuchsia_devices" 74 75CONTROL_PATH_REPLACE_VALUE = " ControlPath /tmp/fuchsia--%r@%h:%p" 76 77FUCHSIA_DEVICE_EMPTY_CONFIG_MSG = "Configuration is empty, abort!" 78FUCHSIA_DEVICE_NOT_LIST_CONFIG_MSG = "Configuration should be a list, abort!" 79FUCHSIA_DEVICE_INVALID_CONFIG = ("Fuchsia device config must be either a str " 80 "or dict. abort! Invalid element %i in %r") 81FUCHSIA_DEVICE_NO_IP_MSG = "No IP address specified, abort!" 82FUCHSIA_COULD_NOT_GET_DESIRED_STATE = "Could not %s %s." 83FUCHSIA_INVALID_CONTROL_STATE = "Invalid control state (%s). abort!" 84FUCHSIA_SSH_CONFIG_NOT_DEFINED = ("Cannot send ssh commands since the " 85 "ssh_config was not specified in the Fuchsia" 86 "device config.") 87 88FUCHSIA_SSH_USERNAME = "fuchsia" 89FUCHSIA_TIME_IN_NANOSECONDS = 1000000000 90 91SL4F_APK_NAME = "com.googlecode.android_scripting" 92DAEMON_INIT_TIMEOUT_SEC = 1 93 94DAEMON_ACTIVATED_STATES = ["running", "start"] 95DAEMON_DEACTIVATED_STATES = ["stop", "stopped"] 96 97FUCHSIA_DEFAULT_LOG_CMD = 'iquery --absolute_paths --cat --format= --recursive' 98FUCHSIA_DEFAULT_LOG_ITEMS = [ 99 '/hub/c/scenic.cmx/[0-9]*/out/objects', 100 '/hub/c/root_presenter.cmx/[0-9]*/out/objects', 101 '/hub/c/wlanstack2.cmx/[0-9]*/out/public', 102 '/hub/c/basemgr.cmx/[0-9]*/out/objects' 103] 104 105FUCHSIA_RECONNECT_AFTER_REBOOT_TIME = 5 106 107ENABLE_LOG_LISTENER = True 108 109CHANNEL_OPEN_TIMEOUT = 5 110 111FUCHSIA_GET_VERSION_CMD = 'cat /config/build-info/version' 112 113FUCHSIA_REBOOT_TYPE_SOFT = 'soft' 114FUCHSIA_REBOOT_TYPE_HARD = 'hard' 115 116FUCHSIA_DEFAULT_CONNECT_TIMEOUT = 60 117FUCHSIA_DEFAULT_COMMAND_TIMEOUT = 60 118 119FUCHSIA_DEFAULT_CLEAN_UP_COMMAND_TIMEOUT = 15 120 121FUCHSIA_COUNTRY_CODE_TIMEOUT = 15 122FUCHSIA_DEFAULT_COUNTRY_CODE_US = 'US' 123 124MDNS_LOOKUP_RETRY_MAX = 3 125 126VALID_ASSOCIATION_MECHANISMS = {None, 'policy', 'drivers'} 127 128 129class FuchsiaDeviceError(signals.ControllerError): 130 pass 131 132 133def create(configs): 134 if not configs: 135 raise FuchsiaDeviceError(FUCHSIA_DEVICE_EMPTY_CONFIG_MSG) 136 elif not isinstance(configs, list): 137 raise FuchsiaDeviceError(FUCHSIA_DEVICE_NOT_LIST_CONFIG_MSG) 138 for index, config in enumerate(configs): 139 if isinstance(config, str): 140 configs[index] = {"ip": config} 141 elif not isinstance(config, dict): 142 raise FuchsiaDeviceError(FUCHSIA_DEVICE_INVALID_CONFIG % 143 (index, configs)) 144 return get_instances(configs) 145 146 147def destroy(fds): 148 for fd in fds: 149 fd.clean_up() 150 del fd 151 152 153def get_info(fds): 154 """Get information on a list of FuchsiaDevice objects. 155 156 Args: 157 fds: A list of FuchsiaDevice objects. 158 159 Returns: 160 A list of dict, each representing info for FuchsiaDevice objects. 161 """ 162 device_info = [] 163 for fd in fds: 164 info = {"ip": fd.ip} 165 device_info.append(info) 166 return device_info 167 168 169def get_instances(fds_conf_data): 170 """Create FuchsiaDevice instances from a list of Fuchsia ips. 171 172 Args: 173 fds_conf_data: A list of dicts that contain Fuchsia device info. 174 175 Returns: 176 A list of FuchsiaDevice objects. 177 """ 178 179 return [FuchsiaDevice(fd_conf_data) for fd_conf_data in fds_conf_data] 180 181 182class FuchsiaDevice: 183 """Class representing a Fuchsia device. 184 185 Each object of this class represents one Fuchsia device in ACTS. 186 187 Attributes: 188 ip: The full address or Fuchsia abstract name to contact the Fuchsia 189 device at 190 log: A logger object. 191 ssh_port: The SSH TCP port number of the Fuchsia device. 192 sl4f_port: The SL4F HTTP port number of the Fuchsia device. 193 ssh_config: The ssh_config for connecting to the Fuchsia device. 194 """ 195 def __init__(self, fd_conf_data): 196 """ 197 Args: 198 fd_conf_data: A dict of a fuchsia device configuration data 199 Required keys: 200 ip: IP address of fuchsia device 201 optional key: 202 sl4_port: Port for the sl4f web server on the fuchsia device 203 (Default: 80) 204 ssh_config: Location of the ssh_config file to connect to 205 the fuchsia device 206 (Default: None) 207 ssh_port: Port for the ssh server on the fuchsia device 208 (Default: 22) 209 """ 210 self.conf_data = fd_conf_data 211 if "ip" not in fd_conf_data: 212 raise FuchsiaDeviceError(FUCHSIA_DEVICE_NO_IP_MSG) 213 self.ip = fd_conf_data["ip"] 214 self.sl4f_port = fd_conf_data.get("sl4f_port", 80) 215 self.ssh_port = fd_conf_data.get("ssh_port", 22) 216 self.ssh_config = fd_conf_data.get("ssh_config", None) 217 218 # Instead of the input ssh_config, a new config with 219 # proper ControlPath values is set and written to 220 # /tmp/temp_fuchsia_ssh_config.config. 221 self._set_control_path_config(self.ssh_config, 222 "/tmp/temp_fuchsia_ssh_config.config") 223 224 self.ssh_config = "/tmp/temp_fuchsia_ssh_config.config" 225 226 self.ssh_username = fd_conf_data.get("ssh_username", 227 FUCHSIA_SSH_USERNAME) 228 self.hard_reboot_on_fail = fd_conf_data.get("hard_reboot_on_fail", 229 False) 230 self.take_bug_report_on_fail = fd_conf_data.get( 231 "take_bug_report_on_fail", False) 232 self.device_pdu_config = fd_conf_data.get("PduDevice", None) 233 self.config_country_code = fd_conf_data.get( 234 'country_code', FUCHSIA_DEFAULT_COUNTRY_CODE_US).upper() 235 self._persistent_ssh_conn = None 236 237 # Whether to use 'policy' or 'drivers' for WLAN connect/disconnect calls 238 # If set to None, wlan is not configured. 239 self.association_mechanism = None 240 # Defaults to policy layer, unless otherwise specified in the config 241 self.default_association_mechanism = fd_conf_data.get( 242 'association_mechanism', 'policy') 243 244 # Whether to clear and preserve existing saved networks and client 245 # connections state, to be restored at device teardown. 246 self.default_preserve_saved_networks = fd_conf_data.get( 247 'preserve_saved_networks', True) 248 249 if utils.is_valid_ipv4_address(self.ip): 250 self.address = "http://{}:{}".format(self.ip, self.sl4f_port) 251 elif utils.is_valid_ipv6_address(self.ip): 252 self.address = "http://[{}]:{}".format(self.ip, self.sl4f_port) 253 else: 254 mdns_ip = None 255 for retry_counter in range(MDNS_LOOKUP_RETRY_MAX): 256 mdns_ip = get_fuchsia_mdns_ipv6_address(self.ip) 257 if mdns_ip: 258 break 259 else: 260 time.sleep(1) 261 if mdns_ip and utils.is_valid_ipv6_address(mdns_ip): 262 self.ip = mdns_ip 263 self.address = "http://[{}]:{}".format(self.ip, self.sl4f_port) 264 else: 265 raise ValueError('Invalid IP: %s' % self.ip) 266 267 self.log = acts_logger.create_tagged_trace_logger( 268 "FuchsiaDevice | %s" % self.ip) 269 270 self.init_address = self.address + "/init" 271 self.cleanup_address = self.address + "/cleanup" 272 self.print_address = self.address + "/print_clients" 273 self.ping_rtt_match = re.compile(r'RTT Min/Max/Avg ' 274 r'= \[ (.*?) / (.*?) / (.*?) \] ms') 275 276 # TODO(): Come up with better client numbering system 277 self.client_id = "FuchsiaClient" + str(random.randint(0, 1000000)) 278 self.test_counter = 0 279 self.serial = re.sub('[.:%]', '_', self.ip) 280 log_path_base = getattr(logging, 'log_path', '/tmp/logs') 281 self.log_path = os.path.join(log_path_base, 282 'FuchsiaDevice%s' % self.serial) 283 self.fuchsia_log_file_path = os.path.join( 284 self.log_path, "fuchsialog_%s_debug.txt" % self.serial) 285 self.log_process = None 286 287 # Grab commands from FuchsiaAudioLib 288 self.audio_lib = FuchsiaAudioLib(self.address, self.test_counter, 289 self.client_id) 290 291 # Grab commands from FuchsiaAvdtpLib 292 self.avdtp_lib = FuchsiaAvdtpLib(self.address, self.test_counter, 293 self.client_id) 294 295 # Grab commands from FuchsiaHfpLib 296 self.hfp_lib = FuchsiaHfpLib(self.address, self.test_counter, 297 self.client_id) 298 299 # Grab commands from FuchsiaLightLib 300 self.light_lib = FuchsiaLightLib(self.address, self.test_counter, 301 self.client_id) 302 303 # Grab commands from FuchsiaBacklightLib 304 self.backlight_lib = FuchsiaBacklightLib(self.address, 305 self.test_counter, 306 self.client_id) 307 308 # Grab commands from FuchsiaBasemgrLib 309 self.basemgr_lib = FuchsiaBasemgrLib(self.address, self.test_counter, 310 self.client_id) 311 # Grab commands from FuchsiaBleLib 312 self.ble_lib = FuchsiaBleLib(self.address, self.test_counter, 313 self.client_id) 314 # Grab commands from FuchsiaBtsLib 315 self.bts_lib = FuchsiaBtsLib(self.address, self.test_counter, 316 self.client_id) 317 # Grab commands from FuchsiaGattcLib 318 self.gattc_lib = FuchsiaGattcLib(self.address, self.test_counter, 319 self.client_id) 320 # Grab commands from FuchsiaGattsLib 321 self.gatts_lib = FuchsiaGattsLib(self.address, self.test_counter, 322 self.client_id) 323 324 # Grab commands from FuchsiaGpioLib 325 self.gpio_lib = FuchsiaGpioLib(self.address, self.test_counter, 326 self.client_id) 327 328 # Grab commands from FuchsiaHardwarePowerStatecontrolLib 329 self.hardware_power_statecontrol_lib = FuchsiaHardwarePowerStatecontrolLib( 330 self.address, self.test_counter, self.client_id) 331 332 # Grab commands from FuchsiaHwinfoLib 333 self.hwinfo_lib = FuchsiaHwinfoLib(self.address, self.test_counter, 334 self.client_id) 335 336 # Grab commands from FuchsiaI2cLib 337 self.i2c_lib = FuchsiaI2cLib(self.address, self.test_counter, 338 self.client_id) 339 340 # Grab commands from FuchsiaInputReportLib 341 self.input_report_lib = FuchsiaInputReportLib(self.address, 342 self.test_counter, 343 self.client_id) 344 345 # Grab commands from FuchsiaKernelLib 346 self.kernel_lib = FuchsiaKernelLib(self.address, self.test_counter, 347 self.client_id) 348 349 # Grab commands from FuchsiaLoggingLib 350 self.logging_lib = FuchsiaLoggingLib(self.address, self.test_counter, 351 self.client_id) 352 353 # Grab commands from FuchsiaNetstackLib 354 self.netstack_lib = FuchsiaNetstackLib(self.address, self.test_counter, 355 self.client_id) 356 357 # Grab commands from FuchsiaLightLib 358 self.ram_lib = FuchsiaRamLib(self.address, self.test_counter, 359 self.client_id) 360 361 # Grab commands from FuchsiaProfileServerLib 362 self.sdp_lib = FuchsiaProfileServerLib(self.address, self.test_counter, 363 self.client_id) 364 365 # Grab commands from FuchsiaRegulatoryRegionLib 366 self.regulatory_region_lib = FuchsiaRegulatoryRegionLib( 367 self.address, self.test_counter, self.client_id) 368 369 # Grab commands from FuchsiaSysInfoLib 370 self.sysinfo_lib = FuchsiaSysInfoLib(self.address, self.test_counter, 371 self.client_id) 372 373 # Grabs command from FuchsiaWlanDeprecatedConfigurationLib 374 self.wlan_deprecated_configuration_lib = FuchsiaWlanDeprecatedConfigurationLib( 375 self.address, self.test_counter, self.client_id) 376 377 # Grab commands from FuchsiaWlanLib 378 self.wlan_lib = FuchsiaWlanLib(self.address, self.test_counter, 379 self.client_id) 380 381 # Grab commands from FuchsiaWlanApPolicyLib 382 self.wlan_ap_policy_lib = FuchsiaWlanApPolicyLib( 383 self.address, self.test_counter, self.client_id) 384 385 # Grab commands from FuchsiaWlanPolicyLib 386 self.wlan_policy_lib = FuchsiaWlanPolicyLib(self.address, 387 self.test_counter, 388 self.client_id) 389 390 # Contains WLAN core functions 391 self.wlan_controller = WlanController(self) 392 393 # Contains WLAN policy functions like save_network, remove_network, etc 394 self.wlan_policy_controller = WlanPolicyController(self) 395 396 self.skip_sl4f = False 397 # Start sl4f on device 398 self.start_services(skip_sl4f=self.skip_sl4f) 399 # Init server 400 self.init_server_connection() 401 402 self.setup_commands = fd_conf_data.get('setup_commands', []) 403 self.teardown_commands = fd_conf_data.get('teardown_commands', []) 404 405 try: 406 self.run_commands_from_config(self.setup_commands) 407 except FuchsiaDeviceError: 408 # Prevent a threading error, since controller isn't fully up yet. 409 self.clean_up() 410 raise FuchsiaDeviceError('Failed to run setup commands.') 411 412 def _set_control_path_config(self, old_config, new_config): 413 """Given an input ssh_config, write to a new config with 414 proper ControlPath values in place. 415 416 Args: 417 old_config: string, path to the input config 418 new_config: string, path to store the new config 419 """ 420 ssh_config_copy = "" 421 422 with open(old_config, 'r') as file: 423 ssh_config_copy = re.sub('(\sControlPath\s.*)', 424 CONTROL_PATH_REPLACE_VALUE, 425 file.read(), 426 flags=re.M) 427 with open(new_config, 'w') as file: 428 file.write(ssh_config_copy) 429 430 @backoff.on_exception( 431 backoff.constant, 432 (ConnectionRefusedError, requests.exceptions.ConnectionError), 433 interval=1.5, 434 max_tries=4) 435 def init_server_connection(self): 436 """Initializes HTTP connection with SL4F server.""" 437 self.log.debug("Initializing server connection") 438 init_data = json.dumps({ 439 "jsonrpc": "2.0", 440 "id": self.build_id(self.test_counter), 441 "method": "sl4f.sl4f_init", 442 "params": { 443 "client_id": self.client_id 444 } 445 }) 446 447 requests.get(url=self.init_address, data=init_data) 448 self.test_counter += 1 449 450 def run_commands_from_config(self, cmd_dicts): 451 """Runs commands on the Fuchsia device from the config file. Useful for 452 device and/or Fuchsia specific configuration. 453 454 Args: 455 cmd_dicts: list of dictionaries containing the following 456 'cmd': string, command to run on device 457 'timeout': int, seconds to wait for command to run (optional) 458 'skip_status_code_check': bool, disregard errors if true 459 """ 460 for cmd_dict in cmd_dicts: 461 try: 462 cmd = cmd_dict['cmd'] 463 except KeyError: 464 raise FuchsiaDeviceError( 465 'To run a command via config, you must provide key "cmd" ' 466 'containing the command string.') 467 468 timeout = cmd_dict.get('timeout', FUCHSIA_DEFAULT_COMMAND_TIMEOUT) 469 # Catch both boolean and string values from JSON 470 skip_status_code_check = 'true' == str( 471 cmd_dict.get('skip_status_code_check', False)).lower() 472 473 self.log.info( 474 'Running command "%s".%s' % 475 (cmd, ' Ignoring result.' if skip_status_code_check else '')) 476 result = self.send_command_ssh( 477 cmd, 478 timeout=timeout, 479 skip_status_code_check=skip_status_code_check) 480 481 if isinstance(result, Exception): 482 raise result 483 484 elif not skip_status_code_check and result.stderr: 485 raise FuchsiaDeviceError( 486 'Error when running command "%s": %s' % 487 (cmd, result.stderr)) 488 489 def build_id(self, test_id): 490 """Concatenates client_id and test_id to form a command_id 491 492 Args: 493 test_id: string, unique identifier of test command 494 """ 495 return self.client_id + "." + str(test_id) 496 497 def configure_wlan(self, 498 association_mechanism=None, 499 preserve_saved_networks=None): 500 """ 501 Readies device for WLAN functionality. If applicable, connects to the 502 policy layer and clears/saves preexisting saved networks. 503 504 Args: 505 association_mechanism: string, 'policy' or 'drivers'. If None, uses 506 the default value from init (can be set by ACTS config) 507 preserve_saved_networks: bool, whether to clear existing saved 508 networks, and preserve them for restoration later. If None, uses 509 the default value from init (can be set by ACTS config) 510 511 Raises: 512 FuchsiaDeviceError, if configuration fails 513 """ 514 515 # Set the country code US by default, or country code provided 516 # in ACTS config 517 self.configure_regulatory_domain(self.config_country_code) 518 519 # If args aren't provided, use the defaults, which can be set in the 520 # config. 521 if association_mechanism is None: 522 association_mechanism = self.default_association_mechanism 523 if preserve_saved_networks is None: 524 preserve_saved_networks = self.default_preserve_saved_networks 525 526 if association_mechanism not in VALID_ASSOCIATION_MECHANISMS: 527 raise FuchsiaDeviceError( 528 'Invalid FuchsiaDevice association_mechanism: %s' % 529 association_mechanism) 530 531 # Allows for wlan to be set up differently in different tests 532 if self.association_mechanism: 533 self.deconfigure_wlan() 534 535 self.association_mechanism = association_mechanism 536 537 self.log.info('Configuring WLAN w/ association mechanism: %s' % 538 association_mechanism) 539 if association_mechanism == 'drivers': 540 self.log.warn( 541 'You may encounter unusual device behavior when using the ' 542 'drivers directly for WLAN. This should be reserved for ' 543 'debugging specific issues. Normal test runs should use the ' 544 'policy layer.') 545 if preserve_saved_networks: 546 self.log.warn( 547 'Unable to preserve saved networks when using drivers ' 548 'association mechanism (requires policy layer control).') 549 else: 550 # This requires SL4F calls, so it can only happen with actual 551 # devices, not with unit tests. 552 self.wlan_policy_controller._configure_wlan( 553 preserve_saved_networks) 554 555 def deconfigure_wlan(self): 556 """ 557 Stops WLAN functionality (if it has been started). Used to allow 558 different tests to use WLAN differently (e.g. some tests require using 559 wlan policy, while the abstract wlan_device can be setup to use policy 560 or drivers) 561 562 Raises: 563 FuchsiaDeviveError, if deconfigure fails. 564 """ 565 if not self.association_mechanism: 566 self.log.debug( 567 'WLAN not configured before deconfigure was called.') 568 return 569 # If using policy, stop client connections. Otherwise, just clear 570 # variables. 571 if self.association_mechanism != 'drivers': 572 self.wlan_policy_controller._deconfigure_wlan() 573 self.association_mechanism = None 574 575 def reboot(self, 576 use_ssh=False, 577 unreachable_timeout=FUCHSIA_DEFAULT_CONNECT_TIMEOUT, 578 ping_timeout=FUCHSIA_DEFAULT_CONNECT_TIMEOUT, 579 ssh_timeout=FUCHSIA_DEFAULT_CONNECT_TIMEOUT, 580 reboot_type=FUCHSIA_REBOOT_TYPE_SOFT, 581 testbed_pdus=None): 582 """Reboot a FuchsiaDevice. 583 584 Soft reboots the device, verifies it becomes unreachable, then verfifies 585 it comes back online. Reinitializes SL4F so the tests can continue. 586 587 Args: 588 use_ssh: bool, if True, use fuchsia shell command via ssh to reboot 589 instead of SL4F. 590 unreachable_timeout: int, time to wait for device to become 591 unreachable. 592 ping_timeout: int, time to wait for device to respond to pings. 593 ssh_timeout: int, time to wait for device to be reachable via ssh. 594 reboot_type: boolFUCHSIA_REBOOT_TYPE_SOFT or 595 FUCHSIA_REBOOT_TYPE_HARD 596 testbed_pdus: list, all testbed PDUs 597 598 Raises: 599 ConnectionError, if device fails to become unreachable, fails to 600 come back up, or if SL4F does not setup correctly. 601 """ 602 # Call Reboot 603 if reboot_type == FUCHSIA_REBOOT_TYPE_SOFT: 604 if use_ssh: 605 self.log.info('Sending reboot command via SSH.') 606 with utils.SuppressLogOutput(): 607 self.clean_up_services() 608 self.send_command_ssh( 609 'dm reboot', 610 timeout=FUCHSIA_RECONNECT_AFTER_REBOOT_TIME, 611 skip_status_code_check=True) 612 else: 613 self.log.info('Calling SL4F reboot command.') 614 with utils.SuppressLogOutput(): 615 self.hardware_power_statecontrol_lib.suspendReboot( 616 timeout=3) 617 self.clean_up_services() 618 elif reboot_type == FUCHSIA_REBOOT_TYPE_HARD: 619 self.log.info('Power cycling FuchsiaDevice (%s)' % self.ip) 620 device_pdu, device_pdu_port = pdu.get_pdu_port_for_device( 621 self.device_pdu_config, testbed_pdus) 622 with utils.SuppressLogOutput(): 623 self.clean_up_services() 624 self.log.info('Killing power to FuchsiaDevice (%s)...' % self.ip) 625 device_pdu.off(str(device_pdu_port)) 626 else: 627 raise ValueError('Invalid reboot type: %s' % reboot_type) 628 # Wait for unreachable 629 self.log.info('Verifying device is unreachable.') 630 timeout = time.time() + unreachable_timeout 631 while (time.time() < timeout): 632 if utils.can_ping(job, self.ip): 633 self.log.debug('Device is still pingable. Retrying.') 634 else: 635 if reboot_type == FUCHSIA_REBOOT_TYPE_HARD: 636 self.log.info('Restoring power to FuchsiaDevice (%s)...' % 637 self.ip) 638 device_pdu.on(str(device_pdu_port)) 639 break 640 else: 641 self.log.info('Device failed to go offline. Reintializing Sl4F.') 642 self.start_services() 643 self.init_server_connection() 644 raise ConnectionError('Device never went down.') 645 self.log.info('Device is unreachable as expected.') 646 if reboot_type == FUCHSIA_REBOOT_TYPE_HARD: 647 self.log.info('Restoring power to FuchsiaDevice (%s)...' % self.ip) 648 device_pdu.on(str(device_pdu_port)) 649 650 self.log.info('Waiting for device to respond to pings.') 651 end_time = time.time() + ping_timeout 652 while time.time() < end_time: 653 if utils.can_ping(job, self.ip): 654 break 655 else: 656 self.log.debug('Device is not pingable. Retrying in 1 second.') 657 time.sleep(1) 658 else: 659 raise ConnectionError('Device never came back online.') 660 self.log.info('Device responded to pings.') 661 662 self.log.info('Waiting for device to allow ssh connection.') 663 end_time = time.time() + ssh_timeout 664 while time.time() < end_time: 665 try: 666 self.send_command_ssh('\n') 667 except Exception: 668 self.log.debug( 669 'Could not SSH to device. Retrying in 1 second.') 670 time.sleep(1) 671 else: 672 break 673 else: 674 raise ConnectionError('Failed to connect to device via SSH.') 675 self.log.info('Device now available via ssh.') 676 677 # Creating new log process, start it, start new persistent ssh session, 678 # start SL4F, and connect via SL4F 679 self.log.info( 680 'Restarting log process and reinitiating SL4F on FuchsiaDevice %s' 681 % self.ip) 682 self.start_services() 683 684 # Verify SL4F is up. 685 self.log.info( 686 'Initiating connection to SL4F and verifying commands can run.') 687 try: 688 self.init_server_connection() 689 self.hwinfo_lib.getDeviceInfo() 690 except Exception as err: 691 raise ConnectionError( 692 'Failed to connect and run command via SL4F. Err: %s' % err) 693 694 # Reconfigure country code, as it does not persist after reboots 695 self.configure_regulatory_domain(self.config_country_code) 696 try: 697 self.run_commands_from_config(self.setup_commands) 698 except FuchsiaDeviceError: 699 # Prevent a threading error, since controller isn't fully up yet. 700 self.clean_up() 701 raise FuchsiaDeviceError( 702 'Failed to run setup commands after reboot.') 703 704 # If wlan was configured before reboot, it must be configured again 705 # after rebooting, as it was before reboot. No preserving should occur. 706 if self.association_mechanism: 707 pre_reboot_association_mechanism = self.association_mechanism 708 # Prevent configure_wlan from thinking it needs to deconfigure first 709 self.association_mechanism = None 710 self.configure_wlan( 711 association_mechanism=pre_reboot_association_mechanism, 712 preserve_saved_networks=False) 713 714 self.log.info( 715 'Device has rebooted, SL4F is reconnected and functional.') 716 717 def send_command_ssh(self, 718 test_cmd, 719 connect_timeout=FUCHSIA_DEFAULT_CONNECT_TIMEOUT, 720 timeout=FUCHSIA_DEFAULT_COMMAND_TIMEOUT, 721 skip_status_code_check=False): 722 """Sends an SSH command to a Fuchsia device 723 724 Args: 725 test_cmd: string, command to send to Fuchsia device over SSH. 726 connect_timeout: Timeout to wait for connecting via SSH. 727 timeout: Timeout to wait for a command to complete. 728 skip_status_code_check: Whether to check for the status code. 729 730 Returns: 731 A SshResults object containing the results of the ssh command. 732 """ 733 command_result = False 734 ssh_conn = None 735 if not self.ssh_config: 736 self.log.warning(FUCHSIA_SSH_CONFIG_NOT_DEFINED) 737 else: 738 try: 739 ssh_conn = create_ssh_connection( 740 self.ip, 741 self.ssh_username, 742 self.ssh_config, 743 ssh_port=self.ssh_port, 744 connect_timeout=connect_timeout) 745 cmd_result_stdin, cmd_result_stdout, cmd_result_stderr = ( 746 ssh_conn.exec_command(test_cmd, timeout=timeout)) 747 if not skip_status_code_check: 748 command_result = SshResults(cmd_result_stdin, 749 cmd_result_stdout, 750 cmd_result_stderr, 751 cmd_result_stdout.channel) 752 except Exception as e: 753 self.log.warning("Problem running ssh command: %s" 754 "\n Exception: %s" % (test_cmd, e)) 755 return e 756 finally: 757 if ssh_conn is not None: 758 ssh_conn.close() 759 return command_result 760 761 def ping(self, 762 dest_ip, 763 count=3, 764 interval=1000, 765 timeout=1000, 766 size=25, 767 additional_ping_params=None): 768 """Pings from a Fuchsia device to an IPv4 address or hostname 769 770 Args: 771 dest_ip: (str) The ip or hostname to ping. 772 count: (int) How many icmp packets to send. 773 interval: (int) How long to wait between pings (ms) 774 timeout: (int) How long to wait before having the icmp packet 775 timeout (ms). 776 size: (int) Size of the icmp packet. 777 additional_ping_params: (str) command option flags to 778 append to the command string 779 780 Returns: 781 A dictionary for the results of the ping. The dictionary contains 782 the following items: 783 status: Whether the ping was successful. 784 rtt_min: The minimum round trip time of the ping. 785 rtt_max: The minimum round trip time of the ping. 786 rtt_avg: The avg round trip time of the ping. 787 stdout: The standard out of the ping command. 788 stderr: The standard error of the ping command. 789 """ 790 rtt_min = None 791 rtt_max = None 792 rtt_avg = None 793 self.log.debug("Pinging %s..." % dest_ip) 794 if not additional_ping_params: 795 additional_ping_params = '' 796 ping_result = self.send_command_ssh( 797 'ping -c %s -i %s -t %s -s %s %s %s' % 798 (count, interval, timeout, size, additional_ping_params, dest_ip)) 799 if isinstance(ping_result, job.Error): 800 ping_result = ping_result.result 801 802 if ping_result.stderr: 803 status = False 804 else: 805 status = True 806 rtt_line = ping_result.stdout.split('\n')[:-1] 807 rtt_line = rtt_line[-1] 808 rtt_stats = re.search(self.ping_rtt_match, rtt_line) 809 rtt_min = rtt_stats.group(1) 810 rtt_max = rtt_stats.group(2) 811 rtt_avg = rtt_stats.group(3) 812 return { 813 'status': status, 814 'rtt_min': rtt_min, 815 'rtt_max': rtt_max, 816 'rtt_avg': rtt_avg, 817 'stdout': ping_result.stdout, 818 'stderr': ping_result.stderr 819 } 820 821 def can_ping(self, 822 dest_ip, 823 count=1, 824 interval=1000, 825 timeout=1000, 826 size=25, 827 additional_ping_params=None): 828 """Returns whether fuchsia device can ping a given dest address""" 829 ping_result = self.ping(dest_ip, 830 count=count, 831 interval=interval, 832 timeout=timeout, 833 size=size, 834 additional_ping_params=additional_ping_params) 835 return ping_result['status'] 836 837 def print_clients(self): 838 """Gets connected clients from SL4F server""" 839 self.log.debug("Request to print clients") 840 print_id = self.build_id(self.test_counter) 841 print_args = {} 842 print_method = "sl4f.sl4f_print_clients" 843 data = json.dumps({ 844 "jsonrpc": "2.0", 845 "id": print_id, 846 "method": print_method, 847 "params": print_args 848 }) 849 850 r = requests.get(url=self.print_address, data=data).json() 851 self.test_counter += 1 852 853 return r 854 855 def clean_up(self): 856 """Cleans up the FuchsiaDevice object, releases any resources it 857 claimed, and restores saved networks is applicable. For reboots, use 858 clean_up_services only. 859 860 Note: Any exceptions thrown in this method must be caught and handled, 861 ensuring that clean_up_services is run. Otherwise, the syslog listening 862 thread will never join and will leave tests hanging. 863 """ 864 # If and only if wlan is configured, and using the policy layer 865 if self.association_mechanism == 'policy': 866 try: 867 self.wlan_policy_controller._clean_up() 868 except Exception as err: 869 self.log.warning('Unable to clean up WLAN Policy layer: %s' % 870 err) 871 try: 872 self.run_commands_from_config(self.teardown_commands) 873 except Exception as err: 874 self.log.warning('Failed to run teardown_commands: %s' % err) 875 876 # This MUST be run, otherwise syslog threads will never join. 877 self.clean_up_services() 878 879 def clean_up_services(self): 880 """ Cleans up FuchsiaDevice services (e.g. SL4F). Subset of clean_up, 881 to be used for reboots, when testing is to continue (as opposed to 882 teardown after testing is finished.) 883 """ 884 cleanup_id = self.build_id(self.test_counter) 885 cleanup_args = {} 886 cleanup_method = "sl4f.sl4f_cleanup" 887 data = json.dumps({ 888 "jsonrpc": "2.0", 889 "id": cleanup_id, 890 "method": cleanup_method, 891 "params": cleanup_args 892 }) 893 894 try: 895 response = requests.get( 896 url=self.cleanup_address, 897 data=data, 898 timeout=FUCHSIA_DEFAULT_CLEAN_UP_COMMAND_TIMEOUT).json() 899 self.log.debug(response) 900 except Exception as err: 901 self.log.exception("Cleanup request failed with %s:" % err) 902 finally: 903 self.test_counter += 1 904 self.stop_services() 905 906 def check_process_state(self, process_name): 907 """Checks the state of a process on the Fuchsia device 908 909 Returns: 910 True if the process_name is running 911 False if process_name is not running 912 """ 913 ps_cmd = self.send_command_ssh("ps") 914 return process_name in ps_cmd.stdout 915 916 def check_process_with_expectation(self, process_name, expectation=None): 917 """Checks the state of a process on the Fuchsia device and returns 918 true or false depending the stated expectation 919 920 Args: 921 process_name: The name of the process to check for. 922 expectation: The state expectation of state of process 923 Returns: 924 True if the state of the process matches the expectation 925 False if the state of the process does not match the expectation 926 """ 927 process_state = self.check_process_state(process_name) 928 if expectation in DAEMON_ACTIVATED_STATES: 929 return process_state 930 elif expectation in DAEMON_DEACTIVATED_STATES: 931 return not process_state 932 else: 933 raise ValueError("Invalid expectation value (%s). abort!" % 934 expectation) 935 936 def control_daemon(self, process_name, action): 937 """Starts or stops a process on a Fuchsia device 938 939 Args: 940 process_name: the name of the process to start or stop 941 action: specify whether to start or stop a process 942 """ 943 if not process_name[-4:] == '.cmx': 944 process_name = '%s.cmx' % process_name 945 unable_to_connect_msg = None 946 process_state = False 947 try: 948 if not self._persistent_ssh_conn: 949 self._persistent_ssh_conn = (create_ssh_connection( 950 self.ip, 951 self.ssh_username, 952 self.ssh_config, 953 ssh_port=self.ssh_port)) 954 self._persistent_ssh_conn.exec_command( 955 "killall %s" % process_name, timeout=CHANNEL_OPEN_TIMEOUT) 956 # This command will effectively stop the process but should 957 # be used as a cleanup before starting a process. It is a bit 958 # confusing to have the msg saying "attempting to stop 959 # the process" after the command already tried but since both start 960 # and stop need to run this command, this is the best place 961 # for the command. 962 if action in DAEMON_ACTIVATED_STATES: 963 self.log.debug("Attempting to start Fuchsia " 964 "devices services.") 965 self._persistent_ssh_conn.exec_command( 966 "run fuchsia-pkg://fuchsia.com/%s#meta/%s &" % 967 (process_name[:-4], process_name)) 968 process_initial_msg = ( 969 "%s has not started yet. Waiting %i second and " 970 "checking again." % 971 (process_name, DAEMON_INIT_TIMEOUT_SEC)) 972 process_timeout_msg = ("Timed out waiting for %s to start." % 973 process_name) 974 unable_to_connect_msg = ("Unable to start %s no Fuchsia " 975 "device via SSH. %s may not " 976 "be started." % 977 (process_name, process_name)) 978 elif action in DAEMON_DEACTIVATED_STATES: 979 process_initial_msg = ("%s is running. Waiting %i second and " 980 "checking again." % 981 (process_name, DAEMON_INIT_TIMEOUT_SEC)) 982 process_timeout_msg = ("Timed out waiting trying to kill %s." % 983 process_name) 984 unable_to_connect_msg = ("Unable to stop %s on Fuchsia " 985 "device via SSH. %s may " 986 "still be running." % 987 (process_name, process_name)) 988 else: 989 raise FuchsiaDeviceError(FUCHSIA_INVALID_CONTROL_STATE % 990 action) 991 timeout_counter = 0 992 while not process_state: 993 self.log.info(process_initial_msg) 994 time.sleep(DAEMON_INIT_TIMEOUT_SEC) 995 timeout_counter += 1 996 process_state = (self.check_process_with_expectation( 997 process_name, expectation=action)) 998 if timeout_counter == (DAEMON_INIT_TIMEOUT_SEC * 3): 999 self.log.info(process_timeout_msg) 1000 break 1001 if not process_state: 1002 raise FuchsiaDeviceError(FUCHSIA_COULD_NOT_GET_DESIRED_STATE % 1003 (action, process_name)) 1004 except Exception as e: 1005 self.log.info(unable_to_connect_msg) 1006 raise e 1007 finally: 1008 if action == 'stop' and (process_name == 'sl4f' 1009 or process_name == 'sl4f.cmx'): 1010 self._persistent_ssh_conn.close() 1011 self._persistent_ssh_conn = None 1012 1013 def check_connect_response(self, connect_response): 1014 if connect_response.get("error") is None: 1015 # Checks the response from SL4F and if there is no error, check 1016 # the result. 1017 connection_result = connect_response.get("result") 1018 if not connection_result: 1019 # Ideally the error would be present but just outputting a log 1020 # message until available. 1021 self.log.debug("Connect call failed, aborting!") 1022 return False 1023 else: 1024 # Returns True if connection was successful. 1025 return True 1026 else: 1027 # the response indicates an error - log and raise failure 1028 self.log.debug("Aborting! - Connect call failed with error: %s" % 1029 connect_response.get("error")) 1030 return False 1031 1032 def check_disconnect_response(self, disconnect_response): 1033 if disconnect_response.get("error") is None: 1034 # Returns True if disconnect was successful. 1035 return True 1036 else: 1037 # the response indicates an error - log and raise failure 1038 self.log.debug("Disconnect call failed with error: %s" % 1039 disconnect_response.get("error")) 1040 return False 1041 1042 # TODO(fxb/64657): Determine more stable solution to country code config on 1043 # device bring up. 1044 def configure_regulatory_domain(self, desired_country_code): 1045 """Allows the user to set the device country code via ACTS config 1046 1047 Usage: 1048 In FuchsiaDevice config, add "country_code": "<CC>" 1049 """ 1050 if self.ssh_config: 1051 # Country code can be None, from ACTS config. 1052 if desired_country_code: 1053 desired_country_code = desired_country_code.upper() 1054 response = self.regulatory_region_lib.setRegion( 1055 desired_country_code) 1056 if response.get('error'): 1057 raise FuchsiaDeviceError( 1058 'Failed to set regulatory domain. Err: %s' % 1059 response['error']) 1060 end_time = time.time() + FUCHSIA_COUNTRY_CODE_TIMEOUT 1061 while time.time() < end_time: 1062 ascii_cc = self.wlan_lib.wlanGetCountry(0).get('result') 1063 # Convert ascii_cc to string, then compare 1064 if ascii_cc and (''.join(chr(c) for c in ascii_cc).upper() 1065 == desired_country_code): 1066 self.log.debug('Country code successfully set to %s.' % 1067 desired_country_code) 1068 return 1069 self.log.debug('Country code not yet updated. Retrying.') 1070 time.sleep(1) 1071 raise FuchsiaDeviceError('Country code never updated to %s' % 1072 desired_country_code) 1073 1074 @backoff.on_exception(backoff.constant, 1075 (FuchsiaSyslogError, socket.timeout), 1076 interval=1.5, 1077 max_tries=4) 1078 def start_services(self, skip_sl4f=False): 1079 """Starts long running services on the Fuchsia device. 1080 1081 1. Start SL4F if not skipped. 1082 1083 Args: 1084 skip_sl4f: Does not attempt to start SL4F if True. 1085 """ 1086 self.log.debug("Attempting to start Fuchsia device services on %s." % 1087 self.ip) 1088 if self.ssh_config: 1089 self.log_process = start_syslog(self.serial, 1090 self.log_path, 1091 self.ip, 1092 self.ssh_username, 1093 self.ssh_config, 1094 ssh_port=self.ssh_port) 1095 1096 if ENABLE_LOG_LISTENER: 1097 try: 1098 self.log_process.start() 1099 except FuchsiaSyslogError as e: 1100 # Before backing off and retrying, stop the syslog if it 1101 # failed to setup correctly, to prevent threading error when 1102 # retrying 1103 self.log_process.stop() 1104 raise 1105 1106 if not skip_sl4f: 1107 self.control_daemon("sl4f.cmx", "start") 1108 1109 out_name = "fuchsia_device_%s_%s.txt" % (self.serial, 'fw_version') 1110 full_out_path = os.path.join(self.log_path, out_name) 1111 fuchsia_version = self.send_command_ssh( 1112 FUCHSIA_GET_VERSION_CMD).stdout 1113 fw_file = open(full_out_path, 'w') 1114 fw_file.write('%s\n' % fuchsia_version) 1115 fw_file.close() 1116 1117 def stop_services(self): 1118 """Stops long running services on the fuchsia device. 1119 1120 Terminate sl4f sessions if exist. 1121 """ 1122 self.log.debug("Attempting to stop Fuchsia device services on %s." % 1123 self.ip) 1124 if self.ssh_config: 1125 try: 1126 self.control_daemon("sl4f.cmx", "stop") 1127 except Exception as err: 1128 self.log.exception("Failed to stop sl4f.cmx with: %s" % err) 1129 if self.log_process: 1130 if ENABLE_LOG_LISTENER: 1131 self.log_process.stop() 1132 1133 def load_config(self, config): 1134 pass 1135 1136 def take_bug_report(self, 1137 test_name, 1138 begin_time, 1139 additional_log_objects=None): 1140 """Takes a bug report on the device and stores it in a file. 1141 1142 Args: 1143 test_name: Name of the test case that triggered this bug report. 1144 begin_time: Epoch time when the test started. 1145 additional_log_objects: A list of additional objects in Fuchsia to 1146 query in the bug report. Must be in the following format: 1147 /hub/c/scenic.cmx/[0-9]*/out/objects 1148 """ 1149 if not additional_log_objects: 1150 additional_log_objects = [] 1151 log_items = [] 1152 matching_log_items = FUCHSIA_DEFAULT_LOG_ITEMS 1153 for additional_log_object in additional_log_objects: 1154 if additional_log_object not in matching_log_items: 1155 matching_log_items.append(additional_log_object) 1156 sn_path = context.get_current_context().get_full_output_path() 1157 os.makedirs(sn_path, exist_ok=True) 1158 time_stamp = acts_logger.normalize_log_line_timestamp( 1159 acts_logger.epoch_to_log_line_timestamp(begin_time)) 1160 out_name = "FuchsiaDevice%s_%s" % ( 1161 self.serial, time_stamp.replace(" ", "_").replace(":", "-")) 1162 snapshot_out_name = f"{out_name}.zip" 1163 out_name = "%s.txt" % out_name 1164 full_out_path = os.path.join(sn_path, out_name) 1165 full_sn_out_path = os.path.join(sn_path, snapshot_out_name) 1166 self.log.info("Taking snapshot for %s on FuchsiaDevice%s." % 1167 (test_name, self.serial)) 1168 if self.ssh_config is not None: 1169 try: 1170 subprocess.run([ 1171 f"ssh -F {self.ssh_config} {self.ip} snapshot > {full_sn_out_path}" 1172 ], 1173 shell=True) 1174 self.log.info("Snapshot saved at: {}".format(full_sn_out_path)) 1175 except Exception as err: 1176 self.log.error("Failed to take snapshot with: {}".format(err)) 1177 1178 system_objects = self.send_command_ssh('iquery --find /hub').stdout 1179 system_objects = system_objects.split() 1180 1181 for matching_log_item in matching_log_items: 1182 for system_object in system_objects: 1183 if re.match(matching_log_item, system_object): 1184 log_items.append(system_object) 1185 1186 log_command = '%s %s' % (FUCHSIA_DEFAULT_LOG_CMD, ' '.join(log_items)) 1187 bug_report_data = self.send_command_ssh(log_command).stdout 1188 1189 bug_report_file = open(full_out_path, 'w') 1190 bug_report_file.write(bug_report_data) 1191 bug_report_file.close() 1192 1193 def take_bt_snoop_log(self, custom_name=None): 1194 """Takes a the bt-snoop log from the device and stores it in a file 1195 in a pcap format. 1196 """ 1197 bt_snoop_path = context.get_current_context().get_full_output_path() 1198 time_stamp = acts_logger.normalize_log_line_timestamp( 1199 acts_logger.epoch_to_log_line_timestamp(time.time())) 1200 out_name = "FuchsiaDevice%s_%s" % ( 1201 self.serial, time_stamp.replace(" ", "_").replace(":", "-")) 1202 out_name = "%s.pcap" % out_name 1203 if custom_name: 1204 out_name = "%s_%s.pcap" % (self.serial, custom_name) 1205 else: 1206 out_name = "%s.pcap" % out_name 1207 full_out_path = os.path.join(bt_snoop_path, out_name) 1208 bt_snoop_data = self.send_command_ssh( 1209 'bt-snoop-cli -d -f pcap').raw_stdout 1210 bt_snoop_file = open(full_out_path, 'wb') 1211 bt_snoop_file.write(bt_snoop_data) 1212 bt_snoop_file.close() 1213 1214 1215class FuchsiaDeviceLoggerAdapter(logging.LoggerAdapter): 1216 def process(self, msg, kwargs): 1217 msg = "[FuchsiaDevice|%s] %s" % (self.extra["ip"], msg) 1218 return msg, kwargs 1219