1from __future__ import absolute_import, division, print_function 2 3from builtins import object 4from collections import namedtuple 5from itertools import chain 6 7from xnu import * 8 9LogBlock = namedtuple('LogBlock', ['blk_id', 'blk']) 10LQEntry = namedtuple('LQEntry', ['state', 'size', 'lmid', 'data']) 11LogStreamElem = namedtuple( 12 'LogStreamElem', ['blk_id', 'offset', 'lsm', 'ftid']) 13 14 15class PPrinter(object): 16 """ Naive yet helpful pretty printer. """ 17 18 def __init__(self, O, kv_indent=17): 19 self._O = O 20 self._kv_fmt = "{:<" + str(kv_indent) + "}" 21 22 def header(self, title, upper_case=False): 23 """ Prints out a header with a given text. """ 24 if upper_case: 25 title = title.upper() 26 print(self._O.format("{VT.Bold}{:s}{VT.EndBold}", title)) 27 28 def table(self, args): 29 """ Switches to a table mode. """ 30 return self._O.table(args) 31 32 @staticmethod 33 def print(*values): 34 """ A simple wrapper around `print` providing same functionality. """ 35 print(*values) 36 37 def kvprint(self, key, fmt, *values): 38 """ Pretty prints aligned `key: values`. The `fmt` argument specifies 39 value(s) format string. 40 """ 41 print(self._kv_fmt.format(key), end=": ") 42 print(fmt.format(*values)) 43 44 @staticmethod 45 def empty_line(): 46 """ Prints an empty line. """ 47 print(" \n") 48 49 50class FTID(object): 51 """ Represents a firehose tracepoint identifier. Decodes the tracepoint 52 and provides details on its fields. 53 """ 54 55 TYPE = { 56 0x00: "default", 57 0x01: "info", 58 0x02: "debug", 59 0x10: "error", 60 0x11: "fault" 61 } 62 63 def __init__(self, ftid): 64 self._ftid = ftid 65 66 @property 67 def value(self): 68 """ Returns a firehose tracepoint id compound value. """ 69 return self._ftid.ftid_value 70 71 @property 72 def namespace(self): 73 """ Returns a tuple of a namespace identifier and its name. """ 74 ns_id = int(self._ftid.ftid._namespace) 75 ns_name = GetEnumName('firehose_tracepoint_namespace_t', 76 ns_id, 'firehose_tracepoint_namespace') 77 return (ns_id, ns_name.split('_')[-1]) 78 79 @property 80 def code(self): 81 """ Returns a tracepoint code value. """ 82 return int(self._ftid.ftid._code) 83 84 @property 85 def flags(self): 86 """ Returns a tuple of a tracepoint flag and its name. """ 87 flag_id = unsigned(self._ftid.ftid._flags) 88 flag_name = GetEnumName('firehose_tracepoint_flags_t', 89 flag_id, '_firehose_tracepoint_flags_') 90 parts = flag_name.split('_') 91 flag_name = parts[0] + ":" + " ".join(parts[2:]) 92 return (flag_id, flag_name) 93 94 @property 95 def type(self): 96 """ Returns a tuple of a tracepoint type and its name. """ 97 # GetEnumName cannot be used because _firehose_tracepoint_type_trace_t 98 # is defined as OS_ENUM which defines values as anonymous enum 99 # unrelated to the type name whatsoever. 100 code_id = int(self._ftid.ftid._type) 101 return (code_id, self.TYPE.get(code_id, "<unknown>")) 102 103 104class LogBlocks(object): 105 """ A base class for objects using log blocks. """ 106 BLOCK_SIZE = 64 107 108 def __init__(self, buf, blk, blk_count, is_ringbuffer): 109 self._buf = buf 110 self._blk = blk 111 self._blk_count = blk_count 112 self._is_ringbuffer = is_ringbuffer 113 114 @property 115 def block_count(self): 116 """ Returns a total block count. """ 117 return self._blk_count 118 119 def block_size(self, block_count=1): 120 """ Returns a space size occupied by a given number of blocks. """ 121 return self.BLOCK_SIZE * block_count 122 123 def block_position(self, cursor): 124 """ Returns a block number and a buffer offset of a log at 125 a provided position (block sequence number). 126 """ 127 blk_id = cursor % self.block_count if self.block_count > 0 else 0 128 return (blk_id, self.block_size(blk_id)) 129 130 def blocks(self, head_block=0): 131 """ Returns a generator of log blocks starting at a provided 132 block position. 133 """ 134 blocks = self._blocks_range(head_block, self.block_count) 135 if self._is_ringbuffer: 136 blocks = chain(blocks, self._blocks_range(0, head_block)) 137 return blocks 138 139 def logs(self, head_block=0): 140 """ Returns a generator of `LogStreamMsg` elements starting at 141 a given block position. 142 """ 143 return (self._log_stream_msg(b.blk_id) for b in self.blocks(head_block) if b.blk) 144 145 def _blocks_range(self, s, e): 146 return (LogBlock(blk_id=i, blk=self._blk[i]) for i in range(s, e)) 147 148 def _log_stream_msg(self, blk_id): 149 lsm_offset = self.block_size(blk_id) 150 lsm = Cast(addressof(self._buf[lsm_offset]), 'log_stream_msg_t *') 151 return LogStreamElem(blk_id=blk_id, 152 offset=lsm_offset, 153 lsm=lsm, 154 ftid=FTID(addressof(lsm.lsm_ft.ft_id))) 155 156 157class LogStream(LogBlocks): 158 """ Represents an OSLog Stream buffer. """ 159 160 def __init__(self, log_stream): 161 super(LogStream, self).__init__(log_stream.ls_buf, 162 log_stream.ls_blk, 163 log_stream.ls_blk_count, 164 True) 165 self._stream = log_stream 166 167 @property 168 def address(self): 169 """ Returns a log stream address. """ 170 return int(self._stream) 171 172 @property 173 def enabled(self): 174 """ Returns true for enabled log stream, false otherwise. """ 175 return self._stream.ls_enabled 176 177 @property 178 def reserved(self): 179 """ Returns a total number of reserved bytes. """ 180 return self._stream.ls_reserved 181 182 @property 183 def logged(self): 184 """ Returns a number of commited bytes and an actual number 185 of logged bytes. 186 """ 187 return (self._stream.ls_commited.v, 188 self._stream.ls_commited.v - self._stream.ls_commited_wraps) 189 190 def sync_cursor(self, cursor): 191 """ Aligns read cursor so it points to the actual beginning 192 of a log stream. 193 """ 194 commited, logged = self.logged 195 read = cursor 196 if read + self.block_count < logged: 197 read = logged 198 if commited >= self.block_count: 199 read -= self.block_count 200 return read % self.block_count 201 202 203class LogStreamCache(LogBlocks): 204 """ Represents an OSLog Stream Cache. 205 """ 206 207 def __init__(self, log_cache): 208 super(LogStreamCache, self).__init__(log_cache.lc_buf, 209 log_cache.lc_blk, 210 log_cache.lc_blk_count, 211 False) 212 self._cache = log_cache 213 214 @property 215 def address(self): 216 """ Returns a log stream cache address. """ 217 return addressof(self._cache) 218 219 @property 220 def stream(self): 221 """ Returns a log stream cached by this instance. 222 """ 223 return LogStream(self._cache.lc_stream) if self._cache.lc_stream else None 224 225 @property 226 def stream_cursor(self): 227 """ Returns a current log stream read cursor. The value is 228 a block sequence of a block to read from next. 229 """ 230 if not self.stream: 231 return 0 232 return self.stream.sync_cursor(self._cache.lc_stream_pos) 233 234 @property 235 def cache_cursor(self): 236 """ Returns a current log cache cursor. The value is a number 237 of a block to read from next. 238 """ 239 return self._cache.lc_blk_pos 240 241 242class MsgBuffer(object): 243 """ Provides access to msgbuf_t ring buffer which is primarily 244 a data type behind system message buffer accessible via dmesg 245 CLI command. 246 """ 247 MSG_MAGIC = 0x063061 248 249 def __init__(self, msgbuf): 250 self._msgbuf = msgbuf 251 size = int(self._msgbuf.msg_size) 252 self._buffer = self._msgbuf.msg_bufc.GetSBValue().GetPointeeData(0, size) 253 self._cache_key = "log.msgbuf." + str(unsigned(self._msgbuf)) 254 255 @property 256 def values(self): 257 """ Returns a list of all log messages. """ 258 values = caching.GetDynamicCacheData(self._cache_key, None) 259 if not values: 260 values = list(self._values()) 261 caching.SaveDynamicCacheData(self._cache_key, values) 262 return values 263 264 def __len__(self): 265 """ Returns a number of log messages in the message buffer. """ 266 return len(self.values) 267 268 def __getitem__(self, i): 269 """ Returns a log message at a given index. """ 270 return self.values[i] 271 272 def __iter__(self): 273 """ Returns an iterator object of log messages. """ 274 return iter(self.values) 275 276 def _values(self): 277 """ Returns a generator object of log messages. """ 278 chars = (c for c in (self._at(i) for i in self._range()) if c != 0) 279 line = bytearray() 280 for c in chars: 281 line.append(c) 282 if chr(c) == '\n': 283 yield six.ensure_str(line.decode('utf-8')) 284 line = bytearray() 285 yield six.ensure_str(line.decode('utf-8')) 286 287 def _at(self, i): 288 """ Returns a character at a given index. """ 289 err = lldb.SBError() 290 c = self._buffer.GetUnsignedInt8(err, i) 291 if not err.Success(): 292 raise ValueError( 293 "Failed to read character at offset " + str(i) + ": " + err.GetCString()) 294 return c 295 296 def _range(self): 297 """ Returns character indices starting at a ring buffer head. """ 298 start = int(self._msgbuf.msg_bufx) 299 size = int(self._msgbuf.msg_size) 300 return ((start + i) % size for i in range(0, size)) 301 302 303class LogQueue(object): 304 """ Represents a kernel log queue. """ 305 306 def __init__(self, cpu, lq): 307 self._cpu = cpu 308 self._lq = lq 309 310 @property 311 def cpu(self): 312 """ Returns a CPU number the log queue is associated with. """ 313 return self._cpu 314 315 @property 316 def ptr(self): 317 """ Returns a pointer to enclosed log_queue_s. """ 318 return self._lq 319 320 @property 321 def address(self): 322 """ Returns a log queue address. """ 323 return int(self.ptr) 324 325 @property 326 def size(self): 327 """ Returns an actual total log queue size. """ 328 slot_size = 1 << unsigned(self._lq.lq_mem_size_order) 329 return self._lq.lq_cnt_mem_active * slot_size 330 331 @property 332 def enqueued(self): 333 """ Returns a generator of logs enqueued in the log queue. """ 334 return self._lq_entries(addressof(self._lq.lq_log_list)) 335 336 @property 337 def dispatched(self): 338 """ Returns a generator of logs dispatched by the log queue. """ 339 return self._lq_entries(addressof(self._lq.lq_dispatch_list)) 340 341 @staticmethod 342 def _lq_entries(lqe_list): 343 """ Returns a generator of LQEntry elements representing given single-linked list. """ 344 def lq_entry(lqe): 345 lqe_state = GetEnumName('log_queue_entry_state_t', 346 lqe.lqe_state, 'LOG_QUEUE_ENTRY_STATE_') 347 return LQEntry(state=lqe_state, size=lqe.lqe_size, lmid=lqe.lqe_lm_id, data=lqe.lqe_payload) 348 return (lq_entry(e) for e in IterateTAILQ_HEAD(lqe_list, 'lqe_link', 's') if e) 349 350 @staticmethod 351 def collect(): 352 """ Returns a list of all per-CPU log queues. """ 353 pcpu_lqs = addressof(kern.GetGlobalVariable('percpu_slot_oslog_queue')) 354 cpus = range(0, kern.globals.zpercpu_early_count) 355 356 def PCPUSlot(pcpu_var, i): 357 addr = unsigned(pcpu_var) + kern.PERCPU_BASE(i) 358 return kern.GetValueFromAddress(addr, pcpu_var) 359 360 return [LogQueue(cpu, PCPUSlot(pcpu_lqs, cpu)) for cpu in cpus] 361 362 363def show_log_stream_logs(pp, logs): 364 """ Pretty prints logs metadata. 365 """ 366 hdr = "{0:>5s} {1:>7s} {2:>6s} {3:>12s} {4:>16s} {5:>8s} {6:>9s} {7:>7s} {8:>8s} {9:>18s}" 367 hdr_labels = ( 368 "BLOCK", "OFFSET", "LENGTH", "TIMESTAMP", "FTID", 369 "TID", "NAMESPACE", "TYPE", "CODE", "FLAGS" 370 ) 371 log_hdr = ( 372 "{log.blk_id:>5d} {log.offset:>7d} {ft.ft_length:>6d} {ts:>12d} " 373 "{ftid.value:>16x} {ft.ft_thread:>8d} {ftid.namespace[1]:>9s} " 374 "{ftid.type[1]:>7s} {ftid.code:>08x} {ftid.flags[1]:>18s}" 375 ) 376 377 log_count = 0 378 with pp.table(hdr.format(*hdr_labels)): 379 for log in logs: 380 pp.print(log_hdr.format(log=log, ts=log.lsm.lsm_ts, 381 ft=log.lsm.lsm_ft, ftid=log.ftid)) 382 log_count += 1 383 pp.print("(Shown {:d} logs)".format(log_count)) 384 385 386def show_log_stream_cache(pp, lsc): 387 """ Pretty prints configuration details of a given log cache. 388 """ 389 pp.header("Stream Cache") 390 391 pp.kvprint("Address", "{:#0x}", lsc.address) 392 pp.kvprint("Size", "{:>d} bytes ({:d} blocks)", 393 lsc.block_size(lsc.block_count), lsc.block_count) 394 pp.kvprint("Next Read Block", "{:d} (Offset: {:d})", 395 *lsc.block_position(lsc.cache_cursor)) 396 397 398def show_log_stream(pp, ls, read_pos): 399 """ Pretty prints configuration details of a given log stream. 400 """ 401 pp.header("Stream") 402 403 if not ls: 404 pp.print("No log stream configured.") 405 return 406 407 commited, logged_bytes = ls.logged 408 pp.kvprint("Address", "{:#0x}", ls.address) 409 pp.kvprint("State", "{:s}", "Enabled" if ls.enabled else "Disabled") 410 pp.kvprint("Size", "{:>d} bytes ({:d} blocks)", 411 ls.block_size(ls.block_count), ls.block_count) 412 pp.kvprint("Reserved", "{:d}", ls.reserved) 413 pp.kvprint("Commited", "{:d}", commited) 414 415 block, offset = ls.block_position(commited) 416 pp.kvprint("Written", "{:d} bytes", logged_bytes) 417 pp.kvprint("Next Write Block", "{:d} (Offset: {:d})", block, offset) 418 419 block, offset = ls.block_position(read_pos) 420 pp.kvprint("Read", "{:d} bytes", read_pos) 421 pp.kvprint("Next Read Block", "{:d} (Offset: {:d})", block, offset) 422 423 424def show_log_stream_stats(pp): 425 """ Pretty prints values of log stream counters. """ 426 pp.header("Statistics") 427 428 pp.kvprint("Total Count", "{:s}", 429 GetSimpleCounter(kern.globals.oslog_s_total_msgcount)) 430 pp.kvprint("Metadata Count", "{:s}", 431 GetSimpleCounter(kern.globals.oslog_s_metadata_msgcount)) 432 pp.kvprint("Streamed Logs", "{:s}", 433 GetSimpleCounter(kern.globals.oslog_s_streamed_msgcount)) 434 pp.kvprint("Dropped Logs", "{:s}", 435 GetSimpleCounter(kern.globals.oslog_s_dropped_msgcount)) 436 pp.kvprint("Invalid Logs", "{:s}", 437 GetSimpleCounter(kern.globals.oslog_s_error_count)) 438 439 440def show_log_stream_info(show_meta, O=None): 441 """ Pretty prints configuration details of OSLog Streaming and 442 its current content. 443 """ 444 pp = PPrinter(O) 445 log_cache = LogStreamCache(kern.globals.log_stream_cache) 446 447 pp.empty_line() 448 pp.header("Overview", True) 449 show_log_stream_stats(pp) 450 show_log_stream_cache(pp, log_cache) 451 show_log_stream(pp, log_cache.stream, log_cache.stream_cursor) 452 453 if not show_meta: 454 return 455 456 pp.empty_line() 457 pp.header("Cached Stream Logs", True) 458 show_log_stream_logs(pp, log_cache.logs(0)) 459 460 if log_cache.stream: 461 pp.empty_line() 462 pp.header("Stream Logs", True) 463 show_log_stream_logs( 464 pp, log_cache.stream.logs(log_cache.stream_cursor)) 465 466 467def show_log_queues(pp, log_queues, show_logs): 468 """ Pretty prints log queue summary and logs. """ 469 hdr = "{:>3s} {:>16s} {:>2s} {:>10s} {:>10s} {:>5s} {:>8s} {:>6s} {:>6s} {:>8s}" 470 hdr_labels = ( 471 "CPU", "ADDRESS", "ON", "STATE", "RECONF", "SLOTS", 472 "SIZE", "AVAIL", "STORED", "EN_ROUTE" 473 ) 474 hdr_lq = ( 475 "{cpu:>3s} {lq.address:>16x} {lq.ptr.lq_ready:>2d} {state:>10s} {reconf:>10s} " 476 "{lq.ptr.lq_cnt_mem_active:>5d} {size:>8d} {lq.ptr.lq_cnt_mem_avail:>6d} " 477 "{enq:>6d} {disp:>8d}" 478 ) 479 480 def show_log_queue(lq, enqueued, dispatched): 481 state = GetEnumName( 482 'lq_mem_state_t', lq._lq.lq_mem_state, 'LQ_MEM_STATE_') 483 reconf = GetEnumName( 484 'lq_req_state_t', lq._lq.lq_req_state, 'LQ_REQ_STATE_') 485 cpu = "N/A" if lq.cpu is None else str(lq.cpu) 486 pp.print(hdr_lq.format(lq=lq, state=state, size=lq.size, reconf=reconf, cpu=cpu, 487 enq=len(enqueued), 488 disp=len(dispatched))) 489 490 if show_logs: 491 for lq in log_queues: 492 lq_enqueued = list(lq.enqueued) 493 lq_dispatched = list(lq.dispatched) 494 pp.empty_line() 495 with pp.table(hdr.format(*hdr_labels)): 496 show_log_queue(lq, lq_enqueued, lq_dispatched) 497 498 pp.empty_line() 499 pp.header("Enqueues Log Messages") 500 show_log_queue_logs(pp, lq_enqueued) 501 502 pp.empty_line() 503 pp.header("Dispatched Log Messages") 504 show_log_queue_logs(pp, lq_dispatched) 505 506 pp.empty_line() 507 return 508 509 with pp.table(hdr.format(*hdr_labels)): 510 for lq in log_queues: 511 show_log_queue(lq, list(lq.enqueued), list(lq.dispatched)) 512 513 514def show_log_queue_logs(pp, lqe_list): 515 """ Pretty prints log queue logs. """ 516 if not lqe_list: 517 pp.print("No log messages present") 518 return 519 520 hdr = ("{:>5s} {:>7s} {:>10s} " 521 "{:>12s} {:>8s} " 522 "{:>16s} {:>9s} {:>7s} {:>8s} {:>18s}") 523 hdr_labels = ( 524 "LM_ID", "LM_SIZE", "STATE", "TIMESTAMP", "LOG_SIZE", 525 "FTID", "NAMESPACE", "TYPE", "CODE", "FLAGS" 526 ) 527 log_hdr = ( 528 "{lqe.lmid:>5x} {lqe.size:>7d} {lqe.state:>10s} " 529 "{d.lp_timestamp:>12d} {d.lp_data_size:>8d} " 530 "{ftid.value:>16x} {ftid.namespace[1]:>9s} " 531 "{ftid.type[1]:>7s} {ftid.code:>08x} {ftid.flags[1]:>18s}" 532 ) 533 with pp.table(hdr.format(*hdr_labels)): 534 for lqe in lqe_list: 535 pp.print(log_hdr.format(lqe=lqe, d=lqe.data, 536 ftid=FTID(lqe.data.lp_ftid))) 537 pp.print("(Shown {:d} logs)".format(len(lqe_list))) 538 539 540@lldb_command('showlogstream', 'L', fancy=True) 541def showLogStream(cmd_args=None, cmd_options=None, O=None): 542 """ Displays the contents of the log stream and the log stream cache. 543 544 showlogstream [-L] 545 546 Options: 547 -L: Show metadata of logs stored in the log stream and the cache 548 """ 549 550 show_meta = "-L" in cmd_options 551 552 show_log_stream_info(show_meta, O) 553 554 555@lldb_command('showlq', 'LC:A:', fancy=True) 556def showLogQueue(cmd_args=None, cmd_options=None, O=None): 557 """ Displays the contents of the log queue. 558 559 usage: showlq [-C cpu_num][-A addr][-L] 560 561 -C n Shows a log queue summary of a selected CPU. 562 -A a Shows a log queue summary at a given address. 563 -L Show metadata of enqueued and dispatched logs 564 565 Options -A and -C are mutually exclusive. 566 If no options provided summaries of all per-CPU log queues are shown. 567 568 Examples: 569 showlq 570 showlq -C 2 -L 571 showlq -A 0xfffffff123456789 -L 572 """ 573 574 log_queues = LogQueue.collect() 575 576 if "-C" in cmd_options and "-A" in cmd_options: 577 raise ArgumentError("Options -A and -C are mutually exclusive.") 578 579 if "-C" in cmd_options: 580 cpu_no = ArgumentStringToInt(cmd_options['-C']) 581 if cpu_no not in range(0, len(log_queues)): 582 print("CPU number out of [0, {:d}) range".format(len(log_queues))) 583 return 584 log_queues = [lq for lq in log_queues if lq.cpu == cpu_no] 585 elif "-A" in cmd_options: 586 addr = ArgumentStringToInt(cmd_options['-A']) 587 log_queues = [lq for lq in log_queues if addr == lq.address] 588 if not log_queues: 589 lq = kern.GetValueFromAddress(addr, 'log_queue_t') 590 log_queues = [LogQueue(None, lq)] 591 592 show_logs = "-L" in cmd_options 593 594 show_log_queues(PPrinter(O), log_queues, show_logs) 595 596 597@lldb_command('showmsgbuf', 'C:F') 598def showMsgBuf(cmd_args=None, cmd_options=None): 599 """ Displays the contents of msgbuf_t type at a given address. 600 601 usage: showmsgbuf [-C <num>][-F] addr 602 603 -C <num> Shows first or last (if negative) specified number of logs. 604 -F Show the content even if the magic key indicates data corruption. 605 """ 606 607 if not cmd_args: 608 print(showMsgBuf.__doc__) 609 return 610 611 addr = kern.GetValueFromAddress(cmd_args[0], 'struct msgbuf *') 612 613 if addr.msg_magic != MsgBuffer.MSG_MAGIC: 614 print("Error: Invalid msgbuf_t magic key {:#x} (expected {:#x}). " 615 "Invalid address or the content is corrupted.".format(addr.msg_magic, MsgBuffer.MSG_MAGIC)) 616 if not "-F" in cmd_options: 617 return 618 619 msgbuf = MsgBuffer(addr) 620 621 if "-C" in cmd_options: 622 count = ArgumentStringToInt(cmd_options['-C']) 623 n = min(abs(count), len(msgbuf)) 624 msgbuf = msgbuf[:n] if count > 0 else msgbuf[-n:] 625 626 for msg in msgbuf: 627 print(msg) 628 629 630@lldb_command('systemlog', 'C:F') 631def systemLog(cmd_args=None, cmd_options=None): 632 """ Displays the contents of the system message buffer. 633 634 usage: systemlog [-C <num>][-F] 635 636 -C <num> Shows first or last (if negative) specified number of logs. 637 -F Show the content even if the magic key indicates data corruption. 638 """ 639 showMsgBuf([unsigned(kern.globals.msgbufp)], cmd_options) 640