#! /usr/bin/env python # Copyright 2025 Google LLC # # Licensed under the Apache License, Version 2.0 (the "License"); # you may not use this file except in compliance with the License. # You may obtain a copy of the License at # # http://www.apache.org/licenses/LICENSE-2.0 # # Unless required by applicable law or agreed to in writing, software # distributed under the License is distributed on an "AS IS" BASIS, # WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. # See the License for the specific language governing permissions and # limitations under the License. # -*- coding: utf8 -*- """ Tests for pebble.loghashing.newlogging """ from pebble.loghashing.newlogging import dehash_line, dehash_line_unformatted from pebble.loghashing.dehashing import dehash_line as legacy_dehash_line import os test_log_dict = {'43': {'file': '../src/fw/activity/activity.c', 'line': '804', 'level': '200', 'color': 'YELLOW', 'msg': 'activity tracking started'}, '114': {'file': '../src/fw/driver/ispp.c', 'line': '1872', 'level': '0', 'color': 'RED', 'msg': 'Start Authentication Process %d (%x) %s'}, '214': {'file': 'pointer_print.c', 'line': '1872', 'level': '0', 'color': 'RED', 'msg': 'My address is %p %p'}, '64856': {'color': 'GREY', 'file': '../src/fw/services/common/clock.c', 'level': '200', 'line': '768', 'msg': 'Changed timezone to id %u, gmtoff is %ld'}, '100000': {'color': 'GREY', 'file': '../src/fw/services/common/string.c', 'level': '200', 'line': '111', 'msg': 'string 1 %s, string 2 %s'}, '11082': {'color': 'GREY', 'file': '../src/fw/resource/resource_storage.c', 'level': '50', 'line': '120', 'msg': '0x%lx != 0x%lx'}, '1073741824': {'color': 'GREY', 'file': 'hc_protocol.c', 'level': '0', 'line': '69', 'msg': 'Init BLE SPI Protocol'}, 'new_logging_version': 'NL0101' } def test_dehash_line(): """ Test for dehash_line() """ # Console Line - No arguments line = "? A 21:35:14.375 :0> NL:{:x}".format(43) assert ("D A 21:35:14.375 activity.c:804> activity tracking started" == dehash_line(line, test_log_dict)) # Console Line - Arguments line = "? A 21:35:14.375 :0> NL:{:x} a a `Success`".format(114) assert ("* A 21:35:14.375 ispp.c:1872> Start Authentication Process 10 (a) Success" == dehash_line(line, test_log_dict)) # Support Line - No arguments line = "2015-09-05 02:16:16:000GMT :0> NL:{:x}".format(43) assert ("2015-09-05 02:16:16:000GMT activity.c:804> activity tracking started" == dehash_line(line, test_log_dict)) # Support Line - Arguments line = "2015-09-05 02:16:19:000GMT :0> NL:{:x} 10 10 `Success`".format(114) assert ("2015-09-05 02:16:19:000GMT ispp.c:1872> Start Authentication Process 16 (10) Success" == dehash_line(line, test_log_dict)) # App Log line = "D A 21:35:14.375 file.c:0> This is an app debug line" assert (line == dehash_line(line, test_log_dict)) # Pointer format conversion line = "2015-09-05 02:16:19:000GMT :0> NL:{:x} 164 1FfF".format(214) assert ("2015-09-05 02:16:19:000GMT pointer_print.c:1872> My address is 164 1fff" == dehash_line(line, test_log_dict)) # Two's compliment negative value line = "2015-09-05 02:16:19:000GMT :0> NL:{:x} 10 ffff8170".format(64856) assert ("2015-09-05 02:16:19:000GMT clock.c:768> Changed timezone to id 16, gmtoff is -32400" == dehash_line(line, test_log_dict)) # Two's compliment negative value line = "2015-09-05 02:16:19:000GMT :0> NL:{:x} 9AEBC155 43073997".format(11082) assert ("2015-09-05 02:16:19:000GMT resource_storage.c:120> 0x9aebc155 != 0x43073997" == dehash_line(line, test_log_dict)) # Empty string parameter - 1 line = "? A 21:35:14.375 :0> NL:{:x} `` `string`".format(100000) assert ("D A 21:35:14.375 string.c:111> string 1 , string 2 string" == dehash_line(line, test_log_dict)) # Empty string parameter - 2 - trailing space line = "? A 21:35:14.375 :0> NL:{:x} `string` `` ".format(100000) assert ("D A 21:35:14.375 string.c:111> string 1 string, string 2 " == dehash_line(line, test_log_dict)) # Empty string parameter - 2 - no trailing space line = "? A 21:35:14.375 :0> NL:{:x} `string` ``".format(100000) assert ("D A 21:35:14.375 string.c:111> string 1 string, string 2 " == dehash_line(line, test_log_dict)) # Missing closing ` line = "? A 21:35:14.375 :0> NL:{:x} `string` `string".format(100000) assert ("D A 21:35:14.375 string.c:111> string 1 string, string 2 string" == dehash_line(line, test_log_dict)) def test_dehash_invalid_parameters(): """ Tests for invalid number of parameters """ # Not enough parameters line = "2015-09-05 02:16:19:000GMT :0> NL:{:x} 164".format(214) assert ("2015-09-05 02:16:19:000GMT pointer_print.c:1872> :0> NL:d6 164 " \ "----> ERROR: not enough arguments for format string" == dehash_line(line, test_log_dict)) # Too many parameters line = "2015-09-05 02:16:19:000GMT :0> NL:{:x} 164 1FfF 17".format(214) assert ("2015-09-05 02:16:19:000GMT pointer_print.c:1872> :0> NL:d6 164 1FfF 17 " \ "----> ERROR: not all arguments converted during string formatting" == dehash_line(line, test_log_dict)) # Unterminated string (last `) line = "2015-09-05 02:16:19:000GMT :0> NL:{:x} 10 10 `Success".format(114) assert ("2015-09-05 02:16:19:000GMT ispp.c:1872> Start Authentication Process 16 (10) Success" == dehash_line(line, test_log_dict)) # Unterminated string (first `) line = "2015-09-05 02:16:19:000GMT :0> NL:{:x} 10 10 Success`".format(114) assert ("2015-09-05 02:16:19:000GMT ispp.c:1872> Start Authentication Process 16 (10) Success" == dehash_line(line, test_log_dict)) # Unterminated string (No `s) line = "2015-09-05 02:16:19:000GMT :0> NL:{:x} 10 10 Success".format(114) assert ("2015-09-05 02:16:19:000GMT ispp.c:1872> Start Authentication Process 16 (10) Success" == dehash_line(line, test_log_dict)) # Invalid hex character line = "2015-09-05 02:16:19:000GMT :0> NL:{:x} 10 1q0 Success".format(114) assert ("2015-09-05 02:16:19:000GMT ispp.c:1872> :0> NL:72 10 1q0 Success " \ "----> ERROR: %x format: a number is required, not str" == dehash_line(line, test_log_dict)) # Unicode line = "? A 21:35:14.375 :0> NL:{:x} `unicode` `Pebble β`".format(100000) assert ("D A 21:35:14.375 string.c:111> string 1 unicode, string 2 Pebble β" == dehash_line(line, test_log_dict)) def test_legacy_dehash_line(): """ Test legacy dehash_line() """ # Console Line - No arguments line = "? A 21:35:14.375 :0> NL:{:x}".format(43) assert ("D A 21:35:14.375 activity.c:804> activity tracking started" == legacy_dehash_line(line, test_log_dict)) def test_unformatted(): """ Test dehash_line_unformatted() """ line = "? A 21:35:14.375 :0> NL:{:x} a a `Success`".format(114) line_dict = dehash_line_unformatted(line, test_log_dict) assert (line_dict['level'] == "0") assert (line_dict['task'] == "A") assert (line_dict['time'] == "21:35:14.375") assert (os.path.basename(line_dict['file']) == "ispp.c") assert (line_dict['line'] == "1872") assert (line_dict['formatted_msg'] == "Start Authentication Process 10 (a) Success") def test_core_number(): """ Test core number decoding """ # Core number 0 line = "? A 21:35:14.375 :0> NL:{:x} a a `Success`".format(114) line_dict = dehash_line_unformatted(line, test_log_dict) assert (line_dict['core_number'] == "0") # Core number 1 line = "? A 21:35:14.375 :0> NL:{:x}".format(1073741824) line_dict = dehash_line_unformatted(line, test_log_dict) assert (line_dict['core_number'] == "1") def test_ble_decode(): """ Test BLE decode. timedate.now() is used, so ignore the date/time """ line = ":0> NL:{:x}".format(1073741824) line_dict = dehash_line_unformatted(line, test_log_dict) assert (line_dict['level'] == "0") assert (line_dict['task'] == "-") assert (os.path.basename(line_dict['file']) == "hc_protocol.c") assert (line_dict['line'] == "69") assert (line_dict['formatted_msg'] == "Init BLE SPI Protocol")