1#!/usr/bin/env python3 2# 3# Copyright 2022 - Google 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 copy 18import re 19import statistics 20 21from acts import signals 22from acts_contrib.test_utils.tel.tel_defines import INVALID_SUB_ID 23from acts_contrib.test_utils.tel.tel_subscription_utils import get_slot_index_from_data_sub_id 24from acts_contrib.test_utils.tel.tel_subscription_utils import get_slot_index_from_voice_sub_id 25from acts_contrib.test_utils.tel.tel_subscription_utils import get_subid_from_slot_index 26 27SETUP_DATA_CALL = 'SETUP_DATA_CALL' 28SETUP_DATA_CALL_REQUEST = '> SETUP_DATA_CALL' 29SETUP_DATA_CALL_RESPONSE = '< SETUP_DATA_CALL' 30IS_CAPTIVEPORTAL = r'isCaptivePortal: isSuccessful()=true' 31 32DEACTIVATE_DATA_CALL = 'DEACTIVATE_DATA_CALL' 33DEACTIVATE_DATA_CALL_REQUEST = '> DEACTIVATE_DATA_CALL' 34DEACTIVATE_DATA_CALL_RESPONSE = '< DEACTIVATE_DATA_CALL' 35UNSOL_DATA_CALL_LIST_CHANGED = 'UNSOL_DATA_CALL_LIST_CHANGED' 36 37IWLAN_DATA_SERVICE = 'IWlanDataService' 38IWLAN_SETUP_DATA_CALL_REQUEST = '> REQUEST_SETUP_DATA_CALL' 39IWLAN_SETUP_DATA_CALL_RESPONSE = 'setupDataCallResponse' 40IWLAN_SEND_ACK = '> send ACK for serial' 41 42IWLAN_DEACTIVATE_DATA_CALL_REQUEST = '> REQUEST_DEACTIVATE_DATA_CALL' 43IWLAN_DEACTIVATE_DATA_CALL_RESPONSE = 'deactivateDataCallResponse' 44 45SET_PREFERRED_DATA_MODEM = 'SET_PREFERRED_DATA_MODEM' 46 47WHI_IWLAN_DATA_SERVICE = 'IwlanDataService' 48WHI_IWLAN_SETUP_DATA_CALL_REQUEST = r'IwlanDataService\[\d\]: Setup data call' 49WHI_IWLAN_SETUP_DATA_CALL_RESPONSE = r'IwlanDataService\[\d\]: Tunnel opened!' 50WHI_IWLAN_DEACTIVATE_DATA_CALL_REQUEST = r'IwlanDataService\[\d\]: Deactivate data call' 51WHI_IWLAN_DEACTIVATE_DATA_CALL_RESPONSE = r'IwlanDataService\[\d\]: Tunnel closed!' 52 53ON_ENABLE_APN_IMS_SLOT0 = 'DCT-C-0 : onEnableApn: apnType=ims, request type=NORMAL' 54ON_ENABLE_APN_IMS_SLOT1 = 'DCT-C-1 : onEnableApn: apnType=ims, request type=NORMAL' 55ON_ENABLE_APN_IMS_HANDOVER_SLOT0 = 'DCT-C-0 : onEnableApn: apnType=ims, request type=HANDOVER' 56ON_ENABLE_APN_IMS_HANDOVER_SLOT1 = 'DCT-C-1 : onEnableApn: apnType=ims, request type=HANDOVER' 57RADIO_ON_4G_SLOT0 = r'GsmCdmaPhone: \[0\] Event EVENT_RADIO_ON Received' 58RADIO_ON_4G_SLOT1 = r'GsmCdmaPhone: \[1\] Event EVENT_RADIO_ON Received' 59RADIO_ON_IWLAN = 'Switching to new default network.*WIFI CONNECTED' 60WIFI_OFF = 'setWifiEnabled.*enable=false' 61ON_IMS_MM_TEL_CONNECTED_4G_SLOT0 = r'ImsPhone: \[0\].*onImsMmTelConnected imsRadioTech=WWAN' 62ON_IMS_MM_TEL_CONNECTED_4G_SLOT1 = r'ImsPhone: \[1\].*onImsMmTelConnected imsRadioTech=WWAN' 63ON_IMS_MM_TEL_CONNECTED_IWLAN_SLOT0 = r'ImsPhone: \[0\].*onImsMmTelConnected imsRadioTech=WLAN' 64ON_IMS_MM_TEL_CONNECTED_IWLAN_SLOT1 = r'ImsPhone: \[1\].*onImsMmTelConnected imsRadioTech=WLAN' 65 66DEFAULT_MO_SMS_BODY = 'MO SMS body not yet found' 67DEFAULT_MT_SMS_BODY = 'MT SMS body not yet found' 68 69MMS_SERVICE = 'MmsService:' 70MMS_SEND_REQUEST_ID_PATTERN = r'SendRequest@(\S+)' 71MMS_DOWNLOAD_REQUEST_ID_PATTERN = r'DownloadRequest@(\S+)' 72MMS_START_NEW_NW_REQUEST = 'start new network request' 73MMS_200_OK = '200 OK' 74 75SMS_SEND_TEXT_MESSAGE = 'smsSendTextMessage' 76MO_SMS_LOGCAT_PATTERN = r'smsSendTextMessage.*"(\S+)", true|false' 77SEND_SMS = 'SEND_SMS' 78SEND_SMS_REQUEST = '> SEND_SMS' 79SEND_SMS_RESPONSE = '< SEND_SMS' 80SEND_SMS_EXPECT_MORE = 'SEND_SMS_EXPECT_MORE' 81UNSOL_RESPONSE_NEW_SMS = '< UNSOL_RESPONSE_NEW_SMS' 82SMS_RECEIVED = 'SmsReceived' 83MT_SMS_CONTENT_PATTERN = 'sl4a.*?SmsReceived.*?"Text":"(.*?)"' 84 85SEND_SMS_OVER_IMS = r'ImsSmsDispatcher \[(\d)\]' 86SEND_SMS_REQUEST_OVER_IMS = 'sendSms: mRetryCount' 87SEND_SMS_RESPONSE_OVER_IMS = 'onSendSmsResult token' 88SMS_RECEIVED_OVER_IMS = 'SMS received' 89SMS_RECEIVED_OVER_IMS_SLOT0 = r'ImsSmsDispatcher \[0\]: SMS received' 90SMS_RECEIVED_OVER_IMS_SLOT1 = r'ImsSmsDispatcher \[1\]: SMS received' 91 92IMS_REGISTERED_CST_SLOT0 = 'IMS_REGISTERED.*CrossStackEpdg.*SLID:0' 93IMS_REGISTERED_CST_SLOT1 = 'IMS_REGISTERED.*CrossStackEpdg.*SLID:1' 94ON_IMS_MM_TEL_CONNECTED_IWLAN_SLOT0 = r'ImsPhone: \[0\].*onImsMmTelConnected imsRadioTech=WLAN' 95ON_IMS_MM_TEL_CONNECTED_IWLAN_SLOT1 = r'ImsPhone: \[1\].*onImsMmTelConnected imsRadioTech=WLAN' 96 97 98def print_nested_dict(ad, d): 99 divider = "------" 100 for k, v in d.items(): 101 if isinstance(v, dict): 102 ad.log.info('%s %s %s', divider, k, divider) 103 print_nested_dict(ad, v) 104 else: 105 ad.log.info('%s: %s', k, v) 106 107 108def get_slot_from_logcat(msg): 109 """Get slot index from specific pattern in logcat 110 111 Args: 112 msg: logcat message string 113 114 Returns: 115 0 for pSIM or 1 for eSIM 116 """ 117 res = re.findall(r'\[(PHONE[\d])\]', msg) 118 try: 119 phone = res[0] 120 except: 121 phone = None 122 return phone 123 124 125def get_apn_from_logcat(msg): 126 """Get APN from logcat 127 128 Args: 129 msg: logcat message string 130 131 Returns: 132 APN 133 """ 134 res = re.findall(r'DataProfile=[^/]+/[^/]+/[^/]+/([^/]+)/', msg) 135 try: 136 apn = res[0] 137 except: 138 apn = None 139 return apn 140 141 142def parse_setup_data_call(ad, apn='internet', dds_switch=False): 143 """Search in logcat for lines containing data call setup procedure. 144 Calculate the data call setup time with given APN and validation 145 time on LTE. 146 147 Args: 148 ad: Android object 149 apn: access point name 150 dds_switch: True for switching DDS. Otherwise False. 151 152 Returns: 153 setup_data_call: Dictionary containing data call setup request and 154 response messages for each data call. The format is shown as 155 below: 156 { 157 message_id: 158 { 159 'request': 160 { 161 'message': logcat message body of data call setup 162 request message 163 'time_stamp': time stamp in text format 164 'datetime_obj': datetime object of time stamp 165 'apn': access point name of this request 166 'phone': 0 for pSIM or 1 for eSIM 167 } 168 'response': 169 { 170 'message': logcat message body of data call setup 171 response message 172 'time_stamp': time stamp in text format 173 'datetime_obj': datetime object of time stamp 174 'cause': failure cause if data call setup failed 175 'cid': PDP context ID 176 'ifname': the name of the interface of the network 177 'phone': 0 for pSIM or 1 for eSIM 178 'unsol_data_call_list_changed': message of 179 unsol_data_call_list_changed 180 'unsol_data_call_list_changed_time': time stamp of 181 the message unsol_data_call_list_changed 182 'is_captive_portal': message of LTE validation pass 183 'data_call_setup_time': time between data call setup 184 request and unsol_data_call_list_changed 185 'validation_time_on_lte': time between data call 186 setup response and LTE validation pass 187 } 188 } 189 } 190 191 data_call_setup_time_list: List. This is a summary of necessary 192 messages of data call setup procedure The format is shown as 193 below: 194 [ 195 { 196 'request': logcat message body of data call setup 197 request message 198 'response': logcat message body of data call setup 199 response message 200 'unsol_data_call_list_changed': message of 201 unsol_data_call_list_changed 202 'start': time stamp of data call setup request 203 'end': time stamp of the message 204 unsol_data_call_list_changed 205 'duration': time between data call setup request and 206 unsol_data_call_list_changed 207 'validation_time_on_lte': time between data call 208 setup response and LTE validation pass 209 } 210 ] 211 212 avg_data_call_setup_time: average of data call setup time 213 214 avg_validation_time_on_lte: average of time for validation time on 215 LTE 216 """ 217 ad.log.info('====== Start to search logcat ====== ') 218 logcat = ad.search_logcat( 219 r'%s\|%s\|%s\|%s' % ( 220 SET_PREFERRED_DATA_MODEM, 221 SETUP_DATA_CALL, 222 UNSOL_DATA_CALL_LIST_CHANGED, IS_CAPTIVEPORTAL)) 223 224 if not logcat: 225 return False 226 227 for msg in logcat: 228 ad.log.info(msg["log_message"]) 229 230 dds_slot = get_slot_index_from_data_sub_id(ad) 231 232 set_preferred_data_modem = {} 233 setup_data_call = {} 234 data_call_setup_time_list = [] 235 last_message_id = None 236 237 for line in logcat: 238 if line['message_id']: 239 if SET_PREFERRED_DATA_MODEM in line['log_message']: 240 set_preferred_data_modem['message'] = line['log_message'] 241 set_preferred_data_modem['time_stamp'] = line['time_stamp'] 242 set_preferred_data_modem[ 243 'datetime_obj'] = line['datetime_obj'] 244 245 if SETUP_DATA_CALL_REQUEST in line['log_message']: 246 found_apn = get_apn_from_logcat(line['log_message']) 247 if found_apn != apn: 248 continue 249 250 phone = get_slot_from_logcat(line['log_message']) 251 if not phone: 252 continue 253 254 if not dds_switch: 255 if str(dds_slot) not in phone: 256 continue 257 258 msg_id = line['message_id'] 259 last_message_id = line['message_id'] 260 if msg_id not in setup_data_call: 261 setup_data_call[msg_id] = {} 262 263 setup_data_call[msg_id]['request'] = { 264 'message': line['log_message'], 265 'time_stamp': line['time_stamp'], 266 'datetime_obj': line['datetime_obj'], 267 'apn': found_apn, 268 'phone': phone} 269 270 if set_preferred_data_modem: 271 setup_data_call[msg_id]['request'][ 272 'set_preferred_data_modem_message'] = set_preferred_data_modem['message'] 273 setup_data_call[msg_id]['request'][ 274 'set_preferred_data_modem_time_stamp'] = set_preferred_data_modem['time_stamp'] 275 setup_data_call[msg_id]['request'][ 276 'set_preferred_data_modem_datetime_obj'] = set_preferred_data_modem['datetime_obj'] 277 set_preferred_data_modem = {} 278 279 if SETUP_DATA_CALL_RESPONSE in line['log_message']: 280 phone = get_slot_from_logcat(line['log_message']) 281 if not phone: 282 continue 283 284 if not dds_switch: 285 if str(dds_slot) not in phone: 286 continue 287 288 msg_id = line['message_id'] 289 if msg_id not in setup_data_call: 290 continue 291 292 if 'request' not in setup_data_call[msg_id]: 293 continue 294 295 last_message_id = line['message_id'] 296 297 setup_data_call[msg_id]['response'] = { 298 'message': line['log_message'], 299 'time_stamp': line['time_stamp'], 300 'datetime_obj': line['datetime_obj'], 301 'cause': '0', 302 'cid': None, 303 'ifname': None, 304 'phone': phone, 305 'unsol_data_call_list_changed': None, 306 'unsol_data_call_list_changed_time': None, 307 'is_captive_portal': None, 308 'data_call_setup_time': None, 309 'validation_time_on_lte': None} 310 311 res = re.findall(r'cause=(\d+)', line['log_message']) 312 try: 313 cause = res[0] 314 setup_data_call[msg_id]['response']['cause'] = cause 315 except: 316 pass 317 318 res = re.findall(r'cid=(\d+)', line['log_message']) 319 try: 320 cid = res[0] 321 setup_data_call[msg_id]['response']['cid'] = cid 322 except: 323 pass 324 325 res = re.findall(r'ifname=(\S+)', line['log_message']) 326 try: 327 ifname = res[0] 328 setup_data_call[msg_id]['response']['ifname'] = ifname 329 except: 330 pass 331 332 if UNSOL_DATA_CALL_LIST_CHANGED in line['log_message']: 333 if not last_message_id: 334 continue 335 336 phone = get_slot_from_logcat(line['log_message']) 337 if not phone: 338 continue 339 340 if not dds_switch: 341 if str(dds_slot) not in phone: 342 continue 343 344 if 'request' not in setup_data_call[last_message_id]: 345 continue 346 347 if 'response' not in setup_data_call[last_message_id]: 348 continue 349 350 cid = setup_data_call[last_message_id]['response']['cid'] 351 if 'cid = %s' % cid not in line['log_message']: 352 continue 353 354 if setup_data_call[last_message_id]['response']['cause'] != '0': 355 continue 356 357 if dds_switch: 358 if 'set_preferred_data_modem_message' not in setup_data_call[ 359 last_message_id]['request']: 360 continue 361 data_call_start_time = setup_data_call[last_message_id][ 362 'request']['set_preferred_data_modem_datetime_obj'] 363 364 else: 365 data_call_start_time = setup_data_call[last_message_id][ 366 'request']['datetime_obj'] 367 368 data_call_end_time = line['datetime_obj'] 369 setup_data_call[last_message_id]['response'][ 370 'unsol_data_call_list_changed_time'] = data_call_end_time 371 setup_data_call[last_message_id]['response'][ 372 'unsol_data_call_list_changed'] = line['log_message'] 373 data_call_setup_time = data_call_end_time - data_call_start_time 374 setup_data_call[last_message_id]['response'][ 375 'data_call_setup_time'] = data_call_setup_time.total_seconds() 376 377 if apn == 'ims': 378 data_call_setup_time_list.append( 379 {'request': setup_data_call[ 380 last_message_id]['request']['message'], 381 'response': setup_data_call[ 382 last_message_id]['response']['message'], 383 'unsol_data_call_list_changed': setup_data_call[ 384 last_message_id]['response'][ 385 'unsol_data_call_list_changed'], 386 'start': data_call_start_time, 387 'end': data_call_end_time, 388 'duration': setup_data_call[last_message_id]['response'][ 389 'data_call_setup_time']}) 390 391 last_message_id = None 392 393 if IS_CAPTIVEPORTAL in line['log_message']: 394 if not last_message_id: 395 continue 396 397 if 'request' not in setup_data_call[last_message_id]: 398 continue 399 400 if 'response' not in setup_data_call[last_message_id]: 401 continue 402 403 if dds_switch: 404 data_call_start_time = setup_data_call[last_message_id][ 405 'request']['set_preferred_data_modem_datetime_obj'] 406 407 else: 408 data_call_start_time = setup_data_call[last_message_id][ 409 'request']['datetime_obj'] 410 411 setup_data_call[last_message_id]['response'][ 412 'is_captive_portal'] = line['log_message'] 413 validation_start_time_on_lte = setup_data_call[ 414 last_message_id]['response']['datetime_obj'] 415 validation_end_time_on_lte = line['datetime_obj'] 416 validation_time_on_lte = ( 417 validation_end_time_on_lte - validation_start_time_on_lte).total_seconds() 418 setup_data_call[last_message_id]['response'][ 419 'validation_time_on_lte'] = validation_time_on_lte 420 421 data_call_setup_time_list.append( 422 {'request': setup_data_call[last_message_id]['request'][ 423 'message'], 424 'response': setup_data_call[last_message_id]['response'][ 425 'message'], 426 'unsol_data_call_list_changed': setup_data_call[ 427 last_message_id]['response']['unsol_data_call_list_changed'], 428 'start': data_call_start_time, 429 'end': setup_data_call[last_message_id]['response'][ 430 'unsol_data_call_list_changed_time'], 431 'duration': setup_data_call[last_message_id]['response'][ 432 'data_call_setup_time'], 433 'validation_time_on_lte': validation_time_on_lte}) 434 435 last_message_id = None 436 437 duration_list = [] 438 for item in data_call_setup_time_list: 439 if 'duration' in item: 440 duration_list.append(item['duration']) 441 442 try: 443 avg_data_call_setup_time = statistics.mean(duration_list) 444 except: 445 avg_data_call_setup_time = None 446 447 validation_time_on_lte_list = [] 448 for item in data_call_setup_time_list: 449 if 'validation_time_on_lte' in item: 450 validation_time_on_lte_list.append( 451 item['validation_time_on_lte']) 452 453 try: 454 avg_validation_time_on_lte = statistics.mean( 455 validation_time_on_lte_list) 456 except: 457 avg_validation_time_on_lte = None 458 459 return ( 460 setup_data_call, 461 data_call_setup_time_list, 462 avg_data_call_setup_time, 463 avg_validation_time_on_lte) 464 465 466def parse_setup_data_call_on_iwlan(ad): 467 """Search in logcat for lines containing data call setup procedure. 468 Calculate the data call setup time with given APN on iwlan. 469 470 Args: 471 ad: Android object 472 apn: access point name 473 474 Returns: 475 setup_data_call: Dictionary containing data call setup request and 476 response messages for each data call. The format is shown as 477 below: 478 { 479 message_id: 480 { 481 'request': 482 { 483 'message': logcat message body of data call setup 484 request message 485 'time_stamp': time stamp in text format 486 'datetime_obj': datetime object of time stamp 487 } 488 'response': 489 { 490 'message': logcat message body of data call setup 491 response message 492 'time_stamp': time stamp in text format 493 'datetime_obj': datetime object of time stamp 494 'cause': failure cause if data call setup failed 495 'data_call_setup_time': time between data call setup 496 request and response 497 } 498 } 499 } 500 501 data_call_setup_time_list: 502 List. This is a summary of mecessary messages of data call setup 503 procedure The format is shown as below: 504 [ 505 { 506 'request': logcat message body of data call setup 507 request message 508 'response': logcat message body of data call setup 509 response message 510 'start': time stamp of data call setup request 511 'end': time stamp of data call setup response 512 'duration': time between data call setup request and 513 response 514 } 515 ] 516 517 avg_data_call_setup_time: average of data call setup time 518 """ 519 ad.log.info('====== Start to search logcat ====== ') 520 logcat = ad.search_logcat(r'%s\|%s' % ( 521 IWLAN_DATA_SERVICE, WHI_IWLAN_DATA_SERVICE)) 522 523 found_iwlan_data_service = 1 524 if not logcat: 525 found_iwlan_data_service = 0 526 527 if not found_iwlan_data_service: 528 ( 529 setup_data_call, 530 data_call_setup_time_list, 531 avg_data_call_setup_time, 532 _) = parse_setup_data_call(ad, apn='ims') 533 534 return ( 535 setup_data_call, 536 data_call_setup_time_list, 537 avg_data_call_setup_time) 538 539 for msg in logcat: 540 ad.log.info(msg["log_message"]) 541 542 setup_data_call = {} 543 data_call_setup_time_list = [] 544 last_message_id = None 545 546 whi_msg_index = None 547 for line in logcat: 548 serial = None 549 cause = None 550 if IWLAN_SETUP_DATA_CALL_REQUEST in line['log_message']: 551 match_res = re.findall( 552 r'%s:\s(\d+)' % IWLAN_DATA_SERVICE, line['log_message']) 553 if match_res: 554 try: 555 serial = match_res[0] 556 except: 557 pass 558 559 if not serial: 560 continue 561 562 msg_id = serial 563 last_message_id = serial 564 if msg_id not in setup_data_call: 565 setup_data_call[msg_id] = {} 566 567 setup_data_call[msg_id]['request'] = { 568 'message': line['log_message'], 569 'time_stamp': line['time_stamp'], 570 'datetime_obj': line['datetime_obj']} 571 572 else: 573 if re.search( 574 WHI_IWLAN_SETUP_DATA_CALL_REQUEST, line['log_message']): 575 if whi_msg_index is None: 576 whi_msg_index = 0 577 else: 578 whi_msg_index = whi_msg_index + 1 579 580 if str(whi_msg_index) not in setup_data_call: 581 setup_data_call[str(whi_msg_index)] = {} 582 583 setup_data_call[str(whi_msg_index)]['request'] = { 584 'message': line['log_message'], 585 'time_stamp': line['time_stamp'], 586 'datetime_obj': line['datetime_obj']} 587 588 if IWLAN_SETUP_DATA_CALL_RESPONSE in line['log_message']: 589 match_res = re.findall(r'Serial = (\d+)', line['log_message']) 590 if match_res: 591 try: 592 serial = match_res[0] 593 except: 594 pass 595 596 if serial: 597 msg_id = serial 598 else: 599 msg_id = last_message_id 600 601 if msg_id not in setup_data_call: 602 continue 603 604 if 'request' not in setup_data_call[msg_id]: 605 continue 606 607 setup_data_call[msg_id]['response'] = { 608 'message': None, 609 'time_stamp': None, 610 'datetime_obj': None, 611 'cause': None, 612 'data_call_setup_time': None} 613 614 match_res = re.findall( 615 r'Fail Cause = (\d+)', line['log_message']) 616 if match_res: 617 try: 618 cause = match_res[0] 619 except: 620 cause = None 621 622 if cause != '0': 623 continue 624 625 setup_data_call[msg_id]['response']['message'] = line[ 626 'log_message'] 627 setup_data_call[msg_id]['response']['time_stamp'] = line[ 628 'time_stamp'] 629 setup_data_call[msg_id]['response']['datetime_obj'] = line[ 630 'datetime_obj'] 631 setup_data_call[msg_id]['response']['cause'] = 0 632 633 data_call_start_time = setup_data_call[last_message_id][ 634 'request']['datetime_obj'] 635 data_call_end_time = line['datetime_obj'] 636 data_call_setup_time = data_call_end_time - data_call_start_time 637 setup_data_call[last_message_id]['response'][ 638 'data_call_setup_time'] = data_call_setup_time.total_seconds() 639 640 data_call_setup_time_list.append( 641 {'request': setup_data_call[last_message_id]['request'][ 642 'message'], 643 'response': setup_data_call[last_message_id]['response'][ 644 'message'], 645 'start': setup_data_call[last_message_id]['request'][ 646 'datetime_obj'], 647 'end': setup_data_call[last_message_id]['response'][ 648 'datetime_obj'], 649 'duration': setup_data_call[last_message_id]['response'][ 650 'data_call_setup_time']}) 651 652 last_message_id = None 653 654 else: 655 if re.search( 656 WHI_IWLAN_SETUP_DATA_CALL_RESPONSE, line['log_message']): 657 if whi_msg_index is None: 658 continue 659 660 if 'response' in setup_data_call[str(whi_msg_index)]: 661 ad.log.error('Duplicated setup data call response is ' 662 'found or the request message is lost.') 663 continue 664 665 setup_data_call[str(whi_msg_index)]['response'] = { 666 'message': line['log_message'], 667 'time_stamp': line['time_stamp'], 668 'datetime_obj': line['datetime_obj'], 669 'data_call_setup_time': None} 670 671 data_call_start_time = setup_data_call[str(whi_msg_index)][ 672 'request']['datetime_obj'] 673 data_call_end_time = line['datetime_obj'] 674 data_call_setup_time = data_call_end_time - data_call_start_time 675 setup_data_call[str(whi_msg_index)]['response'][ 676 'data_call_setup_time'] = data_call_setup_time.total_seconds() 677 678 data_call_setup_time_list.append( 679 {'request': setup_data_call[str(whi_msg_index)][ 680 'request']['message'], 681 'response': setup_data_call[str(whi_msg_index)][ 682 'response']['message'], 683 'start': setup_data_call[str(whi_msg_index)]['request'][ 684 'datetime_obj'], 685 'end': setup_data_call[str(whi_msg_index)]['response'][ 686 'datetime_obj'], 687 'duration': setup_data_call[str(whi_msg_index)][ 688 'response']['data_call_setup_time']}) 689 690 duration_list = [] 691 for item in data_call_setup_time_list: 692 if 'duration' in item: 693 duration_list.append(item['duration']) 694 695 try: 696 avg_data_call_setup_time = statistics.mean(duration_list) 697 except: 698 avg_data_call_setup_time = None 699 700 ad.log.warning('setup_data_call: %s', setup_data_call) 701 ad.log.warning('duration list: %s', duration_list) 702 ad.log.warning('avg_data_call_setup_time: %s', avg_data_call_setup_time) 703 704 return ( 705 setup_data_call, 706 data_call_setup_time_list, 707 avg_data_call_setup_time) 708 709 710def parse_deactivate_data_call(ad): 711 """Search in logcat for lines containing data call deactivation procedure. 712 Calculate the data call deactivation time on LTE. 713 714 Args: 715 ad: Android object 716 717 Returns: 718 deactivate_data_call: Dictionary containing data call deactivation 719 request and response messages for each data call. The format is 720 shown as below: 721 { 722 message_id: 723 { 724 'request': 725 { 726 'message': logcat message body of data call 727 deactivation request message 728 'time_stamp': time stamp in text format 729 'datetime_obj': datetime object of time stamp 730 'cid': PDP context ID 731 'phone': 0 for pSIM or 1 for eSIM 732 } 733 'response': 734 { 735 'message': logcat message body of data call 736 deactivation response message 737 'time_stamp': time stamp in text format 738 'datetime_obj': datetime object of time stamp 739 'phone': 0 for pSIM or 1 for eSIM 740 'unsol_data_call_list_changed': message of 741 unsol_data_call_list_changed 742 'deactivate_data_call_time': time between data call 743 deactivation request and unsol_data_call_list_changed 744 } 745 } 746 } 747 748 deactivate_data_call_time_list: List. This is a summary of necessary 749 messages of data call deactivation procedure The format is shown 750 as below: 751 [ 752 { 753 'request': logcat message body of data call 754 deactivation request message 755 'response': logcat message body of data call 756 deactivation response message 757 'unsol_data_call_list_changed': message of 758 unsol_data_call_list_changed 759 'start': time stamp of data call deactivation request 760 'end': time stamp of the message 761 unsol_data_call_list_changed 762 'duration': time between data call deactivation 763 request and unsol_data_call_list_changed 764 } 765 ] 766 767 avg_deactivate_data_call_time: average of data call deactivation time 768 """ 769 ad.log.info('====== Start to search logcat ====== ') 770 logcat = ad.search_logcat( 771 r'%s\|%s' % (DEACTIVATE_DATA_CALL, UNSOL_DATA_CALL_LIST_CHANGED)) 772 if not logcat: 773 return False 774 775 for msg in logcat: 776 ad.log.info(msg["log_message"]) 777 778 dds_slot = get_slot_index_from_data_sub_id(ad) 779 780 deactivate_data_call = {} 781 deactivate_data_call_time_list = [] 782 last_message_id = None 783 784 for line in logcat: 785 if line['message_id']: 786 if DEACTIVATE_DATA_CALL_REQUEST in line['log_message']: 787 phone = get_slot_from_logcat(line['log_message']) 788 if not phone: 789 continue 790 791 if str(dds_slot) not in phone: 792 continue 793 794 msg_id = line['message_id'] 795 last_message_id = line['message_id'] 796 if msg_id not in deactivate_data_call: 797 deactivate_data_call[msg_id] = {} 798 799 deactivate_data_call[msg_id]['request'] = { 800 'message': line['log_message'], 801 'time_stamp': line['time_stamp'], 802 'datetime_obj': line['datetime_obj'], 803 'cid': None, 804 'phone': dds_slot} 805 806 res = re.findall(r'cid = (\d+)', line['log_message']) 807 try: 808 cid = res[0] 809 deactivate_data_call[msg_id]['request']['cid'] = cid 810 except: 811 pass 812 813 if DEACTIVATE_DATA_CALL_RESPONSE in line['log_message']: 814 phone = get_slot_from_logcat(line['log_message']) 815 if not phone: 816 continue 817 818 if str(dds_slot) not in phone: 819 continue 820 821 msg_id = line['message_id'] 822 if msg_id not in deactivate_data_call: 823 continue 824 825 if 'request' not in deactivate_data_call[msg_id]: 826 continue 827 828 last_message_id = line['message_id'] 829 830 deactivate_data_call[msg_id]['response'] = { 831 'message': line['log_message'], 832 'time_stamp': line['time_stamp'], 833 'datetime_obj': line['datetime_obj'], 834 'phone': dds_slot, 835 'unsol_data_call_list_changed': None, 836 'deactivate_data_call_time': None} 837 838 if UNSOL_DATA_CALL_LIST_CHANGED in line['log_message']: 839 if not last_message_id: 840 continue 841 842 phone = get_slot_from_logcat(line['log_message']) 843 if not phone: 844 continue 845 846 if str(dds_slot) not in phone: 847 continue 848 849 if 'request' not in deactivate_data_call[last_message_id]: 850 continue 851 852 if 'response' not in deactivate_data_call[last_message_id]: 853 continue 854 855 cid = deactivate_data_call[last_message_id]['request']['cid'] 856 if 'cid = %s' % cid not in line['log_message']: 857 continue 858 859 deactivate_data_call_start_time = deactivate_data_call[ 860 last_message_id]['request']['datetime_obj'] 861 deactivate_data_call_end_time = line['datetime_obj'] 862 deactivate_data_call[last_message_id]['response'][ 863 'unsol_data_call_list_changed'] = line['log_message'] 864 deactivate_data_call_time = ( 865 deactivate_data_call_end_time - deactivate_data_call_start_time) 866 deactivate_data_call[last_message_id]['response'][ 867 'deactivate_data_call_time'] = deactivate_data_call_time.total_seconds() 868 deactivate_data_call_time_list.append( 869 {'request': deactivate_data_call[last_message_id][ 870 'request']['message'], 871 'response': deactivate_data_call[last_message_id][ 872 'response']['message'], 873 'unsol_data_call_list_changed': deactivate_data_call[ 874 last_message_id]['response'][ 875 'unsol_data_call_list_changed'], 876 'start': deactivate_data_call_start_time, 877 'end': deactivate_data_call_end_time, 878 'duration': deactivate_data_call_time.total_seconds()}) 879 880 last_message_id = None 881 882 duration_list = [] 883 for item in deactivate_data_call_time_list: 884 if 'duration' in item: 885 duration_list.append(item['duration']) 886 887 try: 888 avg_deactivate_data_call_time = statistics.mean(duration_list) 889 except: 890 avg_deactivate_data_call_time = None 891 892 return ( 893 deactivate_data_call, 894 deactivate_data_call_time_list, 895 avg_deactivate_data_call_time) 896 897 898def parse_deactivate_data_call_on_iwlan(ad): 899 """Search in logcat for lines containing data call deactivation procedure. 900 Calculate the data call deactivation time on iwlan. 901 902 Args: 903 ad: Android object 904 905 Returns: 906 deactivate_data_call: Dictionary containing data call deactivation 907 request and response messages for each data call. The format is 908 shown as below: 909 { 910 message_id: 911 { 912 'request': 913 { 914 'message': logcat message body of data call 915 deactivation request message 916 'time_stamp': time stamp in text format 917 'datetime_obj': datetime object of time stamp 918 } 919 'response': 920 { 921 'message': logcat message body of data call 922 deactivation response message 923 'time_stamp': time stamp in text format 924 'datetime_obj': datetime object of time stamp 925 'send_ack_for_serial_time': time stamp of ACK 926 'deactivate_data_call_time': time between data call 927 deactivation request and ACK 928 } 929 } 930 } 931 932 deactivate_data_call_time_list: List. This is a summary of necessary 933 messages of data call deactivation procedure The format is shown 934 as below: 935 [ 936 { 937 'request': logcat message body of data call 938 deactivation request message 939 'response': logcat message body of data call 940 deactivation response message 941 'start': time stamp of data call deactivation request 942 'end': time stamp of the ACK 943 'duration': time between data call deactivation 944 request and ACK 945 } 946 ] 947 948 avg_deactivate_data_call_time: average of data call deactivation time 949 """ 950 ad.log.info('====== Start to search logcat ====== ') 951 logcat = ad.search_logcat(r'%s\|%s' % ( 952 IWLAN_DATA_SERVICE, WHI_IWLAN_DATA_SERVICE)) 953 954 found_iwlan_data_service = 1 955 if not logcat: 956 found_iwlan_data_service = 0 957 958 if not found_iwlan_data_service: 959 ( 960 deactivate_data_call, 961 deactivate_data_call_time_list, 962 avg_deactivate_data_call_time) = parse_deactivate_data_call(ad) 963 964 return ( 965 deactivate_data_call, 966 deactivate_data_call_time_list, 967 avg_deactivate_data_call_time) 968 969 for msg in logcat: 970 ad.log.info(msg["log_message"]) 971 972 deactivate_data_call = {} 973 deactivate_data_call_time_list = [] 974 last_message_id = None 975 976 whi_msg_index = None 977 for line in logcat: 978 serial = None 979 if IWLAN_DEACTIVATE_DATA_CALL_REQUEST in line['log_message']: 980 match_res = re.findall( 981 r'%s:\s(\d+)' % IWLAN_DATA_SERVICE, line['log_message']) 982 if match_res: 983 try: 984 serial = match_res[0] 985 except: 986 serial = None 987 988 if not serial: 989 continue 990 991 msg_id = serial 992 last_message_id = serial 993 if msg_id not in deactivate_data_call: 994 deactivate_data_call[msg_id] = {} 995 996 deactivate_data_call[msg_id]['request'] = { 997 'message': line['log_message'], 998 'time_stamp': line['time_stamp'], 999 'datetime_obj': line['datetime_obj']} 1000 else: 1001 if re.search(WHI_IWLAN_DEACTIVATE_DATA_CALL_REQUEST, line[ 1002 'log_message']): 1003 if whi_msg_index is None: 1004 whi_msg_index = 0 1005 else: 1006 whi_msg_index = whi_msg_index + 1 1007 1008 if str(whi_msg_index) not in deactivate_data_call: 1009 deactivate_data_call[str(whi_msg_index)] = {} 1010 1011 deactivate_data_call[str(whi_msg_index)]['request'] = { 1012 'message': line['log_message'], 1013 'time_stamp': line['time_stamp'], 1014 'datetime_obj': line['datetime_obj']} 1015 1016 if IWLAN_DEACTIVATE_DATA_CALL_RESPONSE in line['log_message']: 1017 if 'response' not in deactivate_data_call[last_message_id]: 1018 deactivate_data_call[msg_id]['response'] = {} 1019 1020 deactivate_data_call[msg_id]['response'] = { 1021 'message': line['log_message'], 1022 'time_stamp': line['time_stamp'], 1023 'datetime_obj': line['datetime_obj'], 1024 'send_ack_for_serial_time': None, 1025 'deactivate_data_call_time': None} 1026 1027 else: 1028 if re.search(WHI_IWLAN_DEACTIVATE_DATA_CALL_RESPONSE, line[ 1029 'log_message']): 1030 if whi_msg_index is None: 1031 continue 1032 1033 if 'response' in deactivate_data_call[str(whi_msg_index)]: 1034 ad.log.error('Duplicated deactivate data call response' 1035 'is found or the request message is lost.') 1036 continue 1037 1038 deactivate_data_call[str(whi_msg_index)]['response'] = { 1039 'message': line['log_message'], 1040 'time_stamp': line['time_stamp'], 1041 'datetime_obj': line['datetime_obj'], 1042 'deactivate_data_call_time': None} 1043 1044 deactivate_data_call_start_time = deactivate_data_call[ 1045 str(whi_msg_index)]['request']['datetime_obj'] 1046 deactivate_data_call_end_time = line['datetime_obj'] 1047 deactivate_data_call_time = ( 1048 deactivate_data_call_end_time - deactivate_data_call_start_time) 1049 deactivate_data_call[str(whi_msg_index)]['response'][ 1050 'deactivate_data_call_time'] = deactivate_data_call_time.total_seconds() 1051 deactivate_data_call_time_list.append( 1052 {'request': deactivate_data_call[str(whi_msg_index)][ 1053 'request']['message'], 1054 'response': deactivate_data_call[str(whi_msg_index)][ 1055 'response']['message'], 1056 'start': deactivate_data_call_start_time, 1057 'end': deactivate_data_call_end_time, 1058 'duration': deactivate_data_call_time.total_seconds()}) 1059 1060 if IWLAN_SEND_ACK in line['log_message']: 1061 match_res = re.findall( 1062 r'%s:\s(\d+)' % IWLAN_DATA_SERVICE, line['log_message']) 1063 if match_res: 1064 try: 1065 serial = match_res[0] 1066 except: 1067 serial = None 1068 1069 if not serial: 1070 continue 1071 1072 msg_id = serial 1073 1074 if msg_id not in deactivate_data_call: 1075 continue 1076 1077 if 'response' not in deactivate_data_call[msg_id]: 1078 continue 1079 1080 deactivate_data_call[msg_id]['response'][ 1081 'send_ack_for_serial_time'] = line['datetime_obj'] 1082 1083 deactivate_data_call_start_time = deactivate_data_call[msg_id][ 1084 'request']['datetime_obj'] 1085 deactivate_data_call_end_time = line['datetime_obj'] 1086 deactivate_data_call_time = ( 1087 deactivate_data_call_end_time - deactivate_data_call_start_time) 1088 deactivate_data_call[msg_id]['response'][ 1089 'deactivate_data_call_time'] = deactivate_data_call_time.total_seconds() 1090 deactivate_data_call_time_list.append( 1091 {'request': deactivate_data_call[msg_id]['request'][ 1092 'message'], 1093 'response': deactivate_data_call[msg_id]['response'][ 1094 'message'], 1095 'start': deactivate_data_call_start_time, 1096 'end': deactivate_data_call_end_time, 1097 'duration': deactivate_data_call_time.total_seconds()}) 1098 1099 last_message_id = None 1100 1101 duration_list = [] 1102 for item in deactivate_data_call_time_list: 1103 if 'duration' in item: 1104 duration_list.append(item['duration']) 1105 1106 try: 1107 avg_deactivate_data_call_time = statistics.mean(duration_list) 1108 except: 1109 avg_deactivate_data_call_time = None 1110 1111 return ( 1112 deactivate_data_call, 1113 deactivate_data_call_time_list, 1114 avg_deactivate_data_call_time) 1115 1116 1117def parse_ims_reg( 1118 ad, 1119 search_intervals=None, 1120 rat='4g', 1121 reboot_or_apm='reboot', 1122 slot=None): 1123 """Search in logcat for lines containing messages about IMS registration. 1124 1125 Args: 1126 ad: Android object 1127 search_intervals: List. Only lines with time stamp in given time 1128 intervals will be parsed. 1129 E.g., [(begin_time1, end_time1), (begin_time2, end_time2)] 1130 Both begin_time and end_time should be datetime object. 1131 rat: "4g" for IMS over LTE or "iwlan" for IMS over Wi-Fi 1132 reboot_or_apm: specify the scenario "reboot" or "apm" 1133 slot: 0 for pSIM and 1 for eSIM 1134 1135 Returns: 1136 (ims_reg, parsing_fail, avg_ims_reg_duration) 1137 1138 ims_reg: List of dictionaries containing found lines for start and 1139 end time stamps. Each dict represents a cycle of the test. 1140 1141 [ 1142 {'start': message on start time stamp, 1143 'end': message on end time stamp, 1144 'duration': time difference between start and end} 1145 ] 1146 parsing_fail: List of dictionaries containing the cycle number and 1147 missing messages of each failed cycle 1148 1149 [ 1150 'attempt': failed cycle number 1151 'missing_msg' missing messages which should be found 1152 ] 1153 avg_ims_reg_duration: average of the duration in ims_reg 1154 1155 """ 1156 if slot is None: 1157 slot = get_slot_index_from_voice_sub_id(ad) 1158 ad.log.info('Default voice slot: %s', slot) 1159 else: 1160 if get_subid_from_slot_index(ad.log, ad, slot) == INVALID_SUB_ID: 1161 ad.log.error('Slot %s is invalid.', slot) 1162 raise signals.TestFailure('Failed', 1163 extras={'fail_reason': 'Slot %s is invalid.' % slot}) 1164 1165 ad.log.info('Assigned slot: %s', slot) 1166 1167 start_command = { 1168 'reboot': { 1169 '0': {'4g': ON_ENABLE_APN_IMS_SLOT0, 1170 'iwlan': ON_ENABLE_APN_IMS_HANDOVER_SLOT0 + '\|' + ON_ENABLE_APN_IMS_SLOT0}, 1171 '1': {'4g': ON_ENABLE_APN_IMS_SLOT1, 1172 'iwlan': ON_ENABLE_APN_IMS_HANDOVER_SLOT1 + '\|' + ON_ENABLE_APN_IMS_SLOT1} 1173 }, 1174 'apm':{ 1175 '0': {'4g': RADIO_ON_4G_SLOT0, 'iwlan': RADIO_ON_IWLAN}, 1176 '1': {'4g': RADIO_ON_4G_SLOT1, 'iwlan': RADIO_ON_IWLAN} 1177 }, 1178 'wifi_off':{ 1179 '0': {'4g': WIFI_OFF, 'iwlan': WIFI_OFF}, 1180 '1': {'4g': WIFI_OFF, 'iwlan': WIFI_OFF} 1181 }, 1182 } 1183 1184 end_command = { 1185 '0': {'4g': ON_IMS_MM_TEL_CONNECTED_4G_SLOT0, 1186 'iwlan': ON_IMS_MM_TEL_CONNECTED_IWLAN_SLOT0}, 1187 '1': {'4g': ON_IMS_MM_TEL_CONNECTED_4G_SLOT1, 1188 'iwlan': ON_IMS_MM_TEL_CONNECTED_IWLAN_SLOT1} 1189 } 1190 1191 ad.log.info('====== Start to search logcat ======') 1192 logcat = ad.search_logcat('%s\|%s' % ( 1193 start_command[reboot_or_apm][str(slot)][rat], 1194 end_command[str(slot)][rat])) 1195 1196 if not logcat: 1197 raise signals.TestFailure('Failed', 1198 extras={'fail_reason': 'No line matching the given pattern can ' 1199 'be found in logcat.'}) 1200 1201 for msg in logcat: 1202 ad.log.info(msg["log_message"]) 1203 1204 ims_reg = [] 1205 ims_reg_duration_list = [] 1206 parsing_fail = [] 1207 1208 start_command['reboot'] = { 1209 '0': {'4g': ON_ENABLE_APN_IMS_SLOT0, 1210 'iwlan': ON_ENABLE_APN_IMS_HANDOVER_SLOT0 + '|' + ON_ENABLE_APN_IMS_SLOT0}, 1211 '1': {'4g': ON_ENABLE_APN_IMS_SLOT1, 1212 'iwlan': ON_ENABLE_APN_IMS_HANDOVER_SLOT1 + '|' + ON_ENABLE_APN_IMS_SLOT1} 1213 } 1214 1215 keyword_dict = { 1216 'start': start_command[reboot_or_apm][str(slot)][rat], 1217 'end': end_command[str(slot)][rat] 1218 } 1219 1220 for attempt, interval in enumerate(search_intervals): 1221 if isinstance(interval, list): 1222 try: 1223 begin_time, end_time = interval 1224 except Exception as e: 1225 ad.log.error(e) 1226 continue 1227 1228 ad.log.info('Parsing begin time: %s', begin_time) 1229 ad.log.info('Parsing end time: %s', end_time) 1230 1231 temp_keyword_dict = copy.deepcopy(keyword_dict) 1232 for line in logcat: 1233 if begin_time and line['datetime_obj'] < begin_time: 1234 continue 1235 1236 if end_time and line['datetime_obj'] > end_time: 1237 break 1238 1239 for key in temp_keyword_dict: 1240 if temp_keyword_dict[key] and not isinstance( 1241 temp_keyword_dict[key], dict): 1242 res = re.findall( 1243 temp_keyword_dict[key], line['log_message']) 1244 if res: 1245 ad.log.info('Found: %s', line['log_message']) 1246 temp_keyword_dict[key] = { 1247 'message': line['log_message'], 1248 'time_stamp': line['datetime_obj']} 1249 break 1250 1251 for key in temp_keyword_dict: 1252 if temp_keyword_dict[key] == keyword_dict[key]: 1253 ad.log.error( 1254 '"%s" is missing in cycle %s.', 1255 keyword_dict[key], 1256 attempt) 1257 parsing_fail.append({ 1258 'attempt': attempt, 1259 'missing_msg': keyword_dict[key]}) 1260 try: 1261 ims_reg_duration = ( 1262 temp_keyword_dict['end'][ 1263 'time_stamp'] - temp_keyword_dict[ 1264 'start'][ 1265 'time_stamp']).total_seconds() 1266 ims_reg_duration_list.append(ims_reg_duration) 1267 ims_reg.append({ 1268 'start': temp_keyword_dict['start'][ 1269 'message'], 1270 'end': temp_keyword_dict['end'][ 1271 'message'], 1272 'duration': ims_reg_duration}) 1273 except Exception as e: 1274 ad.log.error(e) 1275 1276 try: 1277 avg_ims_reg_duration = statistics.mean(ims_reg_duration_list) 1278 except: 1279 avg_ims_reg_duration = None 1280 1281 return ims_reg, parsing_fail, avg_ims_reg_duration 1282 1283 1284def parse_mo_sms(logcat): 1285 """Search in logcat for lines containing messages about SMS sending on 1286 LTE. 1287 1288 Args: 1289 logcat: List containing lines of logcat 1290 1291 Returns: 1292 send_sms: Dictionary containing found lines for each SMS 1293 request and response messages together with their time stamps. 1294 { 1295 'message_id':{ 1296 'request':{ 1297 'message': logcat message body of SMS request 1298 'time_stamp': time stamp in text format 1299 'datetime_obj': datetime object of the time stamp 1300 }, 1301 'response':{ 1302 'message': logcat message body of SMS response 1303 'time_stamp': time stamp in text format 1304 'datetime_obj': datetime object of the time stamp 1305 'sms_delivery_time': time between SMS request and 1306 response 1307 } 1308 } 1309 } 1310 1311 summary: the format is listed below: 1312 { 1313 'request': logcat message body of SMS request 1314 'response': logcat message body of SMS response 1315 'unsol_response_new_sms': unsolicited response message upon 1316 SMS receiving on MT UE 1317 'sms_body': message body of SMS 1318 'mo_start': time stamp of MO SMS request message 1319 'mo_end': time stamp of MO SMS response message 1320 'mo_signal_duration': time between MO SMS request and response 1321 'delivery_time': time between MO SMS request and 1322 unsol_response_new_sms on MT UE 1323 } 1324 1325 avg_setup_time: average of mo_signal_duration 1326 """ 1327 send_sms = {} 1328 summary = [] 1329 sms_body = DEFAULT_MO_SMS_BODY 1330 msg_id = None 1331 if not logcat: 1332 return False 1333 1334 for line in logcat: 1335 res = re.findall(MO_SMS_LOGCAT_PATTERN, line['log_message']) 1336 if res: 1337 try: 1338 sms_body = res[0] 1339 except: 1340 sms_body = 'Cannot find MO SMS body' 1341 1342 if line['message_id']: 1343 msg_id = line['message_id'] 1344 if SEND_SMS_REQUEST in line[ 1345 'log_message'] and SEND_SMS_EXPECT_MORE not in line[ 1346 'log_message']: 1347 if msg_id not in send_sms: 1348 send_sms[msg_id] = {} 1349 1350 send_sms[msg_id]['sms_body'] = sms_body 1351 sms_body = DEFAULT_MO_SMS_BODY 1352 send_sms[msg_id]['request'] = { 1353 'message': line['log_message'], 1354 'time_stamp': line['time_stamp'], 1355 'datetime_obj': line['datetime_obj']} 1356 1357 if SEND_SMS_RESPONSE in line[ 1358 'log_message'] and SEND_SMS_EXPECT_MORE not in line[ 1359 'log_message']: 1360 if msg_id not in send_sms: 1361 continue 1362 1363 if 'request' not in send_sms[msg_id]: 1364 continue 1365 1366 if "error" in line['log_message']: 1367 continue 1368 1369 send_sms[msg_id]['response'] = { 1370 'message': line['log_message'], 1371 'time_stamp': line['time_stamp'], 1372 'datetime_obj': line['datetime_obj'], 1373 'sms_delivery_time': None} 1374 1375 mo_sms_start_time = send_sms[msg_id]['request'][ 1376 'datetime_obj'] 1377 mo_sms_end_time = line['datetime_obj'] 1378 sms_delivery_time = mo_sms_end_time - mo_sms_start_time 1379 send_sms[msg_id]['response'][ 1380 'sms_delivery_time'] = sms_delivery_time.total_seconds() 1381 summary.append( 1382 {'request': send_sms[msg_id]['request']['message'], 1383 'response': send_sms[msg_id]['response']['message'], 1384 'unsol_response_new_sms': None, 1385 'sms_body': send_sms[msg_id]['sms_body'], 1386 'mo_start': mo_sms_start_time, 1387 'mo_end': mo_sms_end_time, 1388 'mo_signal_duration': sms_delivery_time.total_seconds(), 1389 'delivery_time': None}) 1390 1391 duration_list = [] 1392 for item in summary: 1393 if 'mo_signal_duration' in item: 1394 duration_list.append(item['mo_signal_duration']) 1395 1396 try: 1397 avg_setup_time = statistics.mean(duration_list) 1398 except: 1399 avg_setup_time = None 1400 1401 return send_sms, summary, avg_setup_time 1402 1403 1404def parse_mo_sms_iwlan(logcat): 1405 """Search in logcat for lines containing messages about SMS sending on 1406 iwlan. 1407 1408 Args: 1409 logcat: List containing lines of logcat 1410 1411 Returns: 1412 send_sms: Dictionary containing found lines for each SMS 1413 request and response messages together with their time stamps. 1414 { 1415 'message_id':{ 1416 'request':{ 1417 'message': logcat message body of SMS request 1418 'time_stamp': time stamp in text format 1419 'datetime_obj': datetime object of the time stamp 1420 }, 1421 'response':{ 1422 'message': logcat message body of SMS response 1423 'time_stamp': time stamp in text format 1424 'datetime_obj': datetime object of the time stamp 1425 'sms_delivery_time': time between SMS request and 1426 response 1427 } 1428 } 1429 } 1430 1431 summary: List containing dictionaries for each SMS. The format is 1432 listed below: 1433 [ 1434 { 1435 'request': logcat message body of SMS request 1436 'response': logcat message body of SMS response 1437 'sms_body': message body of SMS 1438 'mo_start': time stamp of MO SMS request message 1439 'mo_end': time stamp of MO SMS response message 1440 'mo_signal_duration': time between MO SMS request and 1441 response 1442 'delivery_time': time between MO SMS request and 1443 MT SMS received message 1444 } 1445 ] 1446 1447 avg_setup_time: average of mo_signal_duration 1448 """ 1449 send_sms = {} 1450 summary = [] 1451 sms_body = DEFAULT_MO_SMS_BODY 1452 msg_id = None 1453 1454 if not logcat: 1455 return False 1456 1457 for line in logcat: 1458 res = re.findall(MO_SMS_LOGCAT_PATTERN, line['log_message']) 1459 if res: 1460 try: 1461 sms_body = res[0] 1462 except: 1463 sms_body = 'Cannot find MO SMS body' 1464 1465 if SEND_SMS_REQUEST_OVER_IMS in line['log_message']: 1466 if msg_id is None: 1467 msg_id = '0' 1468 else: 1469 msg_id = str(int(msg_id) + 1) 1470 1471 if msg_id not in send_sms: 1472 send_sms[msg_id] = {} 1473 1474 send_sms[msg_id]['sms_body'] = sms_body 1475 sms_body = DEFAULT_MO_SMS_BODY 1476 send_sms[msg_id]['request'] = { 1477 'message': line['log_message'], 1478 'time_stamp': line['time_stamp'], 1479 'datetime_obj': line['datetime_obj']} 1480 1481 if SEND_SMS_RESPONSE_OVER_IMS in line['log_message']: 1482 1483 if msg_id not in send_sms: 1484 continue 1485 1486 if 'request' not in send_sms[msg_id]: 1487 continue 1488 1489 if "error" in line['log_message']: 1490 continue 1491 1492 send_sms[msg_id]['response'] = { 1493 'message': line['log_message'], 1494 'time_stamp': line['time_stamp'], 1495 'datetime_obj': line['datetime_obj'], 1496 'sms_delivery_time': None} 1497 1498 mo_sms_start_time = send_sms[msg_id]['request'][ 1499 'datetime_obj'] 1500 mo_sms_end_time = line['datetime_obj'] 1501 sms_delivery_time = mo_sms_end_time - mo_sms_start_time 1502 send_sms[msg_id]['response'][ 1503 'sms_delivery_time'] = sms_delivery_time.total_seconds() 1504 summary.append( 1505 {'request': send_sms[msg_id]['request']['message'], 1506 'response': send_sms[msg_id]['response']['message'], 1507 'unsol_response_new_sms': None, 1508 'sms_body': send_sms[msg_id]['sms_body'], 1509 'mo_start': mo_sms_start_time, 1510 'mo_end': mo_sms_end_time, 1511 'mo_signal_duration': sms_delivery_time.total_seconds(), 1512 'delivery_time': None}) 1513 1514 duration_list = [] 1515 for item in summary: 1516 if 'mo_signal_duration' in item: 1517 duration_list.append(item['mo_signal_duration']) 1518 1519 try: 1520 avg_setup_time = statistics.mean(duration_list) 1521 except: 1522 avg_setup_time = None 1523 1524 return send_sms, summary, avg_setup_time 1525 1526 1527def parse_mt_sms(logcat): 1528 """Search in logcat for lines containing messages about SMS receiving on 1529 LTE. 1530 1531 Args: 1532 logcat: List containing lines of logcat 1533 1534 Returns: 1535 received_sms_list: List containing dictionaries for each received 1536 SMS. The format is listed below: 1537 [ 1538 { 1539 'message': logcat message body of unsolicited response 1540 message 1541 'sms_body': message body of SMS 1542 'time_stamp': time stamp of unsolicited response message in 1543 text format 1544 'datetime_obj': datetime object of the time stamp 1545 'sms_delivery_time': time between SMS request and 1546 response 1547 } 1548 ] 1549 """ 1550 received_sms_list = [] 1551 if not logcat: 1552 return False 1553 1554 for line in logcat: 1555 if UNSOL_RESPONSE_NEW_SMS in line['log_message']: 1556 1557 # if received_sms_list: 1558 # if received_sms_list[-1]['sms_body'] is None: 1559 # del received_sms_list[-1] 1560 1561 received_sms_list.append( 1562 {'message': line['log_message'], 1563 'sms_body': DEFAULT_MT_SMS_BODY, 1564 'time_stamp': line['time_stamp'], 1565 'datetime_obj': line['datetime_obj']}) 1566 else: 1567 res = re.findall(MT_SMS_CONTENT_PATTERN, line['log_message']) 1568 1569 if res: 1570 try: 1571 sms_body = res[0] 1572 except: 1573 sms_body = 'Cannot find MT SMS body' 1574 1575 if received_sms_list[-1]['sms_body'] == DEFAULT_MT_SMS_BODY: 1576 received_sms_list[-1]['sms_body'] = sms_body 1577 continue 1578 1579 return received_sms_list 1580 1581 1582def parse_mt_sms_iwlan(logcat): 1583 """Search in logcat for lines containing messages about SMS receiving on 1584 iwlan. 1585 1586 Args: 1587 logcat: List containing lines of logcat 1588 1589 Returns: 1590 received_sms_list: List containing dictionaries for each received 1591 SMS. The format is listed below: 1592 [ 1593 { 1594 'message': logcat message body of SMS received message 1595 'sms_body': message body of SMS 1596 'time_stamp': time stamp of SMS received message in 1597 text format 1598 'datetime_obj': datetime object of the time stamp 1599 } 1600 ] 1601 """ 1602 received_sms_list = [] 1603 if not logcat: 1604 return False 1605 1606 for line in logcat: 1607 if re.findall( 1608 SMS_RECEIVED_OVER_IMS_SLOT0 + '|' + SMS_RECEIVED_OVER_IMS_SLOT1, 1609 line['log_message']): 1610 received_sms_list.append( 1611 {'message': line['log_message'], 1612 'sms_body': DEFAULT_MT_SMS_BODY, 1613 'time_stamp': line['time_stamp'], 1614 'datetime_obj': line['datetime_obj']}) 1615 else: 1616 res = re.findall(MT_SMS_CONTENT_PATTERN, line['log_message']) 1617 1618 if res: 1619 try: 1620 sms_body = res[0] 1621 except: 1622 sms_body = 'Cannot find MT SMS body' 1623 1624 if received_sms_list[-1]['sms_body'] == DEFAULT_MT_SMS_BODY: 1625 received_sms_list[-1]['sms_body'] = sms_body 1626 continue 1627 1628 return received_sms_list 1629 1630 1631def parse_sms_delivery_time(log, ad_mo, ad_mt, rat='4g'): 1632 """Calculate the SMS delivery time (time between MO SMS request and MT 1633 unsolicited response message or MT SMS received message) from logcat 1634 of both MO and MT UE. 1635 1636 Args: 1637 ad_mo: MO Android object 1638 ad_mt: MT Android object 1639 rat: '4g' for LTE and 'iwlan' for iwlan 1640 1641 Returns: 1642 None 1643 """ 1644 ad_mo.log.info('====== Start to search logcat ====== ') 1645 mo_logcat = ad_mo.search_logcat( 1646 r'%s\|%s\|%s\|%s' % ( 1647 SMS_SEND_TEXT_MESSAGE, 1648 SEND_SMS, 1649 SEND_SMS_REQUEST_OVER_IMS, 1650 SEND_SMS_RESPONSE_OVER_IMS)) 1651 ad_mt.log.info('====== Start to search logcat ====== ') 1652 mt_logcat = ad_mt.search_logcat( 1653 r'%s\|%s\|%s' % ( 1654 UNSOL_RESPONSE_NEW_SMS, SMS_RECEIVED, SMS_RECEIVED_OVER_IMS)) 1655 1656 for msg in mo_logcat: 1657 ad_mo.log.info(msg["log_message"]) 1658 for msg in mt_logcat: 1659 ad_mt.log.info(msg["log_message"]) 1660 1661 if rat == 'iwlan': 1662 _, mo_sms_summary, avg = parse_mo_sms_iwlan(mo_logcat) 1663 received_sms_list = parse_mt_sms_iwlan(mt_logcat) 1664 else: 1665 _, mo_sms_summary, avg = parse_mo_sms(mo_logcat) 1666 received_sms_list = parse_mt_sms(mt_logcat) 1667 1668 sms_delivery_time = [] 1669 for mo_sms in mo_sms_summary: 1670 for mt_sms in received_sms_list: 1671 if mo_sms['sms_body'] == mt_sms['sms_body']: 1672 mo_sms['delivery_time'] = ( 1673 mt_sms['datetime_obj'] - mo_sms['mo_start']).total_seconds() 1674 mo_sms['unsol_response_new_sms'] = mt_sms['message'] 1675 sms_delivery_time.append(mo_sms['delivery_time']) 1676 1677 try: 1678 avg_sms_delivery_time = statistics.mean(sms_delivery_time) 1679 except: 1680 avg_sms_delivery_time = None 1681 1682 ad_mo.log.info('====== MO SMS summary ======') 1683 for item in mo_sms_summary: 1684 ad_mo.log.info('------------------') 1685 print_nested_dict(ad_mo, item) 1686 ad_mt.log.info('====== Received SMS list ======') 1687 for item in received_sms_list: 1688 ad_mt.log.info('------------------') 1689 print_nested_dict(ad_mt, item) 1690 1691 ad_mo.log.info('%s SMS were actually sent.', len(mo_sms_summary)) 1692 ad_mt.log.info('%s SMS were actually received.', len(received_sms_list)) 1693 ad_mo.log.info('Average MO SMS setup time: %.2f sec.', avg) 1694 log.info( 1695 'Average SMS delivery time: %.2f sec.', avg_sms_delivery_time) 1696 1697 1698def parse_mms(ad_mo, ad_mt): 1699 """Search in logcat for lines containing messages about SMS sending and 1700 receiving. Calculate MO & MT MMS setup time. 1701 1702 Args: 1703 ad_mo: MO Android object 1704 ad_mt: MT Android object 1705 1706 Returns: 1707 send_mms: Dictionary containing each sent MMS. The format is shown 1708 as below: 1709 { 1710 mms_msg_id: 1711 { 1712 MMS_START_NEW_NW_REQUEST: 1713 { 1714 'time_stamp': time stamp of MMS request on MO UE in 1715 text format 1716 'datetime_obj': datetime object of time stamp 1717 }, 1718 MMS_200_OK: 1719 { 1720 'time_stamp': time stamp of '200 OK' for MMS request 1721 in text format 1722 'datetime_obj': datetime object of time stamp 1723 'setup_time': MO MMS setup time. Time between MMS 1724 request and 200 OK 1725 } 1726 } 1727 1728 } 1729 1730 mo_avg_setup_time: average of MO MMS setup time 1731 1732 receive_mms： Dictionary containing each received MMS. The format is 1733 shown as below: 1734 { 1735 mms_msg_id: 1736 { 1737 MMS_START_NEW_NW_REQUEST: 1738 { 1739 'time_stamp': time stamp of MMS request on MT UE in 1740 text format 1741 'datetime_obj': datetime object of time stamp 1742 }, 1743 MMS_200_OK: 1744 { 1745 'time_stamp': time stamp of '200 OK' for MMS request 1746 in text format 1747 'datetime_obj': datetime object of time stamp 1748 'setup_time': MT MMS setup time. Time between MMS 1749 request and 200 OK 1750 } 1751 } 1752 1753 } 1754 1755 mt_avg_setup_time: average of MT MMS setup time 1756 """ 1757 send_mms = {} 1758 receive_mms = {} 1759 mo_setup_time_list = [] 1760 mt_setup_time_list = [] 1761 1762 ad_mo.log.info('====== Start to search logcat ====== ') 1763 mo_logcat = ad_mo.search_logcat(MMS_SERVICE) 1764 for msg in mo_logcat: 1765 ad_mo.log.info(msg["log_message"]) 1766 1767 ad_mt.log.info('====== Start to search logcat ====== ') 1768 mt_logcat = ad_mt.search_logcat(MMS_SERVICE) 1769 for msg in mt_logcat: 1770 ad_mt.log.info(msg["log_message"]) 1771 1772 if not mo_logcat or not mt_logcat: 1773 return False 1774 1775 for line in mo_logcat: 1776 find_res = re.findall( 1777 MMS_SEND_REQUEST_ID_PATTERN, line['log_message']) 1778 1779 message_id = None 1780 try: 1781 message_id = find_res[0] 1782 except: 1783 pass 1784 1785 if message_id: 1786 mms_msg_id = message_id 1787 if mms_msg_id not in send_mms: 1788 send_mms[mms_msg_id] = {} 1789 if MMS_START_NEW_NW_REQUEST in line['log_message']: 1790 send_mms[mms_msg_id][MMS_START_NEW_NW_REQUEST] = { 1791 'time_stamp': line['time_stamp'], 1792 'datetime_obj': line['datetime_obj']} 1793 1794 if MMS_200_OK in line['log_message']: 1795 send_mms[mms_msg_id][MMS_200_OK] = { 1796 'time_stamp': line['time_stamp'], 1797 'datetime_obj': line['datetime_obj'], 1798 'setup_time': None} 1799 1800 if MMS_START_NEW_NW_REQUEST in send_mms[mms_msg_id]: 1801 setup_time = line['datetime_obj'] - send_mms[mms_msg_id][ 1802 MMS_START_NEW_NW_REQUEST]['datetime_obj'] 1803 send_mms[mms_msg_id][MMS_200_OK][ 1804 'setup_time'] = setup_time.total_seconds() 1805 mo_setup_time_list.append(setup_time.total_seconds()) 1806 1807 for line in mt_logcat: 1808 find_res = re.findall( 1809 MMS_DOWNLOAD_REQUEST_ID_PATTERN, line['log_message']) 1810 1811 message_id = None 1812 try: 1813 message_id = find_res[0] 1814 except: 1815 pass 1816 1817 if message_id: 1818 mms_msg_id = message_id 1819 if mms_msg_id not in receive_mms: 1820 receive_mms[mms_msg_id] = {} 1821 if MMS_START_NEW_NW_REQUEST in line['log_message']: 1822 receive_mms[mms_msg_id][MMS_START_NEW_NW_REQUEST] = { 1823 'time_stamp': line['time_stamp'], 1824 'datetime_obj': line['datetime_obj']} 1825 1826 if MMS_200_OK in line['log_message']: 1827 receive_mms[mms_msg_id][MMS_200_OK] = { 1828 'time_stamp': line['time_stamp'], 1829 'datetime_obj': line['datetime_obj'], 1830 'setup_time': None} 1831 1832 if MMS_START_NEW_NW_REQUEST in receive_mms[mms_msg_id]: 1833 setup_time = line['datetime_obj'] - receive_mms[ 1834 mms_msg_id][MMS_START_NEW_NW_REQUEST]['datetime_obj'] 1835 receive_mms[mms_msg_id][MMS_200_OK][ 1836 'setup_time'] = setup_time.total_seconds() 1837 mt_setup_time_list.append(setup_time.total_seconds()) 1838 1839 try: 1840 mo_avg_setup_time = statistics.mean(mo_setup_time_list) 1841 except: 1842 mo_avg_setup_time = None 1843 1844 try: 1845 mt_avg_setup_time = statistics.mean(mt_setup_time_list) 1846 except: 1847 mt_avg_setup_time = None 1848 1849 return send_mms, mo_avg_setup_time, receive_mms, mt_avg_setup_time 1850 1851 1852def parse_cst_reg(ad, slot, search_intervals=None): 1853 """ Check if IMS CST and WFC is registered at given slot by parsing logcat. 1854 1855 Args: 1856 ad: Android object 1857 slot: 0 for pSIM and 1 for eSIM 1858 search_intervals: List. Only lines with time stamp in given time 1859 intervals will be parsed. 1860 E.g., [(begin_time1, end_time1), (begin_time2, end_time2)] 1861 Both begin_time and end_time should be datetime object. 1862 1863 Returns: List of attampt number and error messages of not found pattern 1864 of failing cycles 1865 """ 1866 cst = { 1867 'ims_registered': { 1868 '0': IMS_REGISTERED_CST_SLOT0, 1869 '1': IMS_REGISTERED_CST_SLOT1 1870 }, 1871 'iwlan': { 1872 '0': ON_IMS_MM_TEL_CONNECTED_IWLAN_SLOT0, 1873 '1': ON_IMS_MM_TEL_CONNECTED_IWLAN_SLOT1 1874 } 1875 } 1876 ad.log.info('====== Start to search logcat ====== ') 1877 logcat = ad.search_logcat( 1878 '%s\|%s' % ( 1879 cst['ims_registered'][str(slot)], cst['iwlan'][str(slot)])) 1880 1881 for line in logcat: 1882 msg = line["log_message"] 1883 ad.log.info(msg) 1884 1885 parsing_fail = [] 1886 keyword_dict = { 1887 'ims_registered': cst['ims_registered'][str(slot)], 1888 'iwlan': cst['iwlan'][str(slot)] 1889 } 1890 for attempt, interval in enumerate(search_intervals): 1891 if isinstance(interval, list): 1892 try: 1893 begin_time, end_time = interval 1894 except Exception as e: 1895 ad.log.error(e) 1896 continue 1897 1898 ad.log.info('Parsing begin time: %s', begin_time) 1899 ad.log.info('Parsing end time: %s', end_time) 1900 1901 temp_keyword_dict = copy.deepcopy(keyword_dict) 1902 for line in logcat: 1903 if begin_time and line['datetime_obj'] < begin_time: 1904 continue 1905 1906 if end_time and line['datetime_obj'] > end_time: 1907 break 1908 1909 for key in temp_keyword_dict: 1910 if temp_keyword_dict[key] and not isinstance( 1911 temp_keyword_dict[key], dict): 1912 res = re.findall( 1913 temp_keyword_dict[key], line['log_message']) 1914 if res: 1915 ad.log.info('Found: %s', line['log_message']) 1916 temp_keyword_dict[key] = { 1917 'message': line['log_message'], 1918 'time_stamp': line['datetime_obj']} 1919 break 1920 1921 for key in temp_keyword_dict: 1922 if temp_keyword_dict[key] == keyword_dict[key]: 1923 ad.log.error( 1924 '"%s" is missing in cycle %s.', 1925 keyword_dict[key], 1926 attempt+1) 1927 parsing_fail.append({ 1928 'attempt': attempt+1, 1929 'missing_msg': keyword_dict[key]}) 1930 1931 return parsing_fail 1932 1933 1934def check_ims_cst_reg(ad, slot, search_interval=None): 1935 """ Check if IMS CST is registered at given slot by parsing logcat. 1936 1937 Args: 1938 ad: Android object 1939 slot: 0 for pSIM and 1 for eSIM 1940 search_intervals: List. Only lines with time stamp in given time 1941 intervals will be parsed. 1942 E.g., [(begin_time1, end_time1), (begin_time2, end_time2)] 1943 Both begin_time and end_time should be datetime object. 1944 1945 Returns: True for successful registration. Otherwise False 1946 """ 1947 ims_cst_reg = { 1948 '0': IMS_REGISTERED_CST_SLOT0, 1949 '1': IMS_REGISTERED_CST_SLOT1 1950 } 1951 logcat = ad.search_logcat('%s' % ims_cst_reg[str(slot)]) 1952 if isinstance(search_interval, list): 1953 try: 1954 begin_time, end_time = search_interval 1955 except Exception as e: 1956 ad.log.error(e) 1957 1958 for line in logcat: 1959 if begin_time and line['datetime_obj'] < begin_time: 1960 continue 1961 1962 if end_time and line['datetime_obj'] > end_time: 1963 break 1964 1965 res = re.findall(ims_cst_reg[str(slot)], line['log_message']) 1966 if res: 1967 ad.log.info( 1968 'IMS CST is registered due to following message ' 1969 'found: %s', line['log_message']) 1970 return True 1971 return False