1from collections import namedtuple 2from itertools import chain 3 4from xnu import * 5 6LogBlock = namedtuple('LogBlock', ['blk_id', 'blk']) 7LQEntry = namedtuple('LQEntry', ['state', 'size', 'lmid', 'data']) 8LogStreamElem = namedtuple( 9 'LogStreamElem', ['blk_id', 'offset', 'lsm', 'ftid']) 10 11 12class PPrinter(object): 13 """ Naive yet helpful pretty printer. """ 14 15 def __init__(self, O, kv_indent=17): 16 self._O = O 17 self._kv_fmt = "{:<" + str(kv_indent) + "}" 18 19 def header(self, title, upper_case=False): 20 """ Prints out a header with a given text. """ 21 if upper_case: 22 title = title.upper() 23 print(self._O.format("{VT.Bold}{:s}{VT.EndBold}", title)) 24 25 def table(self, args): 26 """ Switches to a table mode. """ 27 return self._O.table(args) 28 29 @staticmethod 30 def print(*values): 31 """ A simple wrapper around `print` providing same functionality. """ 32 print(*values) 33 34 def kvprint(self, key, fmt, *values): 35 """ Pretty prints aligned `key: values`. The `fmt` argument specifies 36 value(s) format string. 37 """ 38 print(self._kv_fmt.format(key), end=": ") 39 print(fmt.format(*values)) 40 41 @staticmethod 42 def empty_line(): 43 """ Prints an empty line. """ 44 print(" \n") 45 46 47class FTID(object): 48 """ Represents a firehose tracepoint identifier. Decodes the tracepoint 49 and provides details on its fields. 50 """ 51 52 TYPE = { 53 0x00: "default", 54 0x01: "info", 55 0x02: "debug", 56 0x10: "error", 57 0x11: "fault" 58 } 59 60 def __init__(self, ftid): 61 self._ftid = ftid 62 63 @property 64 def value(self): 65 """ Returns a firehose tracepoint id compound value. """ 66 return self._ftid.ftid_value 67 68 @property 69 def namespace(self): 70 """ Returns a tuple of a namespace identifier and its name. """ 71 ns_id = int(self._ftid.ftid._namespace) 72 ns_name = GetEnumName('firehose_tracepoint_namespace_t', 73 ns_id, 'firehose_tracepoint_namespace') 74 return (ns_id, ns_name.split('_')[-1]) 75 76 @property 77 def code(self): 78 """ Returns a tracepoint code value. """ 79 return int(self._ftid.ftid._code) 80 81 @property 82 def flags(self): 83 """ Returns a tuple of a tracepoint flag and its name. """ 84 flag_id = unsigned(self._ftid.ftid._flags) 85 flag_name = GetEnumName('firehose_tracepoint_flags_t', 86 flag_id, '_firehose_tracepoint_flags_') 87 parts = flag_name.split('_') 88 flag_name = parts[0] + ":" + " ".join(parts[2:]) 89 return (flag_id, flag_name) 90 91 @property 92 def type(self): 93 """ Returns a tuple of a tracepoint type and its name. """ 94 # GetEnumName cannot be used because _firehose_tracepoint_type_trace_t 95 # is defined as OS_ENUM which defines values as anonymous enum 96 # unrelated to the type name whatsoever. 97 code_id = int(self._ftid.ftid._type) 98 return (code_id, self.TYPE.get(code_id, "<unknown>")) 99 100 101class LogBlocks(object): 102 """ A base class for objects using log blocks. """ 103 BLOCK_SIZE = 64 104 105 def __init__(self, buf, blk, blk_count, is_ringbuffer): 106 self._buf = buf 107 self._blk = blk 108 self._blk_count = blk_count 109 self._is_ringbuffer = is_ringbuffer 110 111 @property 112 def block_count(self): 113 """ Returns a total block count. """ 114 return self._blk_count 115 116 def block_size(self, block_count=1): 117 """ Returns a space size occupied by a given number of blocks. """ 118 return self.BLOCK_SIZE * block_count 119 120 def block_position(self, cursor): 121 """ Returns a block number and a buffer offset of a log at 122 a provided position (block sequence number). 123 """ 124 blk_id = cursor % self.block_count if self.block_count > 0 else 0 125 return (blk_id, self.block_size(blk_id)) 126 127 def blocks(self, head_block=0): 128 """ Returns a generator of log blocks starting at a provided 129 block position. 130 """ 131 blocks = self._blocks_range(head_block, self.block_count) 132 if self._is_ringbuffer: 133 blocks = chain(blocks, self._blocks_range(0, head_block)) 134 return blocks 135 136 def logs(self, head_block=0): 137 """ Returns a generator of `LogStreamMsg` elements starting at 138 a given block position. 139 """ 140 return (self._log_stream_msg(b.blk_id) for b in self.blocks(head_block) if b.blk) 141 142 def _blocks_range(self, s, e): 143 return (LogBlock(blk_id=i, blk=self._blk[i]) for i in range(s, e)) 144 145 def _log_stream_msg(self, blk_id): 146 lsm_offset = self.block_size(blk_id) 147 lsm = Cast(addressof(self._buf[lsm_offset]), 'log_stream_msg_t *') 148 return LogStreamElem(blk_id=blk_id, 149 offset=lsm_offset, 150 lsm=lsm, 151 ftid=FTID(addressof(lsm.lsm_ft.ft_id))) 152 153 154class LogStream(LogBlocks): 155 """ Represents an OSLog Stream buffer. """ 156 157 def __init__(self, log_stream): 158 super().__init__(log_stream.ls_buf, 159 log_stream.ls_blk, 160 log_stream.ls_blk_count, 161 True) 162 self._stream = log_stream 163 164 @property 165 def address(self): 166 """ Returns a log stream address. """ 167 return int(self._stream) 168 169 @property 170 def enabled(self): 171 """ Returns true for enabled log stream, false otherwise. """ 172 return self._stream.ls_enabled 173 174 @property 175 def reserved(self): 176 """ Returns a total number of reserved bytes. """ 177 return self._stream.ls_reserved 178 179 @property 180 def logged(self): 181 """ Returns a number of commited bytes and an actual number 182 of logged bytes. 183 """ 184 return (self._stream.ls_commited.v, 185 self._stream.ls_commited.v - self._stream.ls_commited_wraps) 186 187 def sync_cursor(self, cursor): 188 """ Aligns read cursor so it points to the actual beginning 189 of a log stream. 190 """ 191 commited, logged = self.logged 192 read = cursor 193 if read + self.block_count < logged: 194 read = logged 195 if commited >= self.block_count: 196 read -= self.block_count 197 return read % self.block_count 198 199 200class LogStreamCache(LogBlocks): 201 """ Represents an OSLog Stream Cache. 202 """ 203 204 def __init__(self, log_cache): 205 super().__init__(log_cache.lc_buf, 206 log_cache.lc_blk, 207 log_cache.lc_blk_count, 208 False) 209 self._cache = log_cache 210 211 @property 212 def address(self): 213 """ Returns a log stream cache address. """ 214 return addressof(self._cache) 215 216 @property 217 def stream(self): 218 """ Returns a log stream cached by this instance. 219 """ 220 return LogStream(self._cache.lc_stream) if self._cache.lc_stream else None 221 222 @property 223 def stream_cursor(self): 224 """ Returns a current log stream read cursor. The value is 225 a block sequence of a block to read from next. 226 """ 227 if not self.stream: 228 return 0 229 return self.stream.sync_cursor(self._cache.lc_stream_pos) 230 231 @property 232 def cache_cursor(self): 233 """ Returns a current log cache cursor. The value is a number 234 of a block to read from next. 235 """ 236 return self._cache.lc_blk_pos 237 238 239class MsgBuffer(object): 240 """ Provides access to msgbuf_t ring buffer which is primarily 241 a data type behind system message buffer accessible via dmesg 242 CLI command. 243 """ 244 MSG_MAGIC = 0x063061 245 246 def __init__(self, msgbuf): 247 self._msgbuf = msgbuf 248 size = int(self._msgbuf.msg_size) 249 self._buffer = self._msgbuf.msg_bufc.GetSBValue().GetPointeeData(0, size) 250 251 def __eq__(self, other): 252 return unsigned(self._msgbuf) == unsigned(other._msgbuf) 253 254 def __hash__(self): 255 return hash(unsigned(self._msgbuf)) 256 257 @dyn_cached_property 258 def values(self, target=None): 259 """ Returns a list of all log messages. """ 260 261 return list(self._values()) 262 263 def __len__(self): 264 """ Returns a number of log messages in the message buffer. """ 265 return len(self.values) 266 267 def __getitem__(self, i): 268 """ Returns a log message at a given index. """ 269 return self.values[i] 270 271 def __iter__(self): 272 """ Returns an iterator object of log messages. """ 273 return iter(self.values) 274 275 def _values(self): 276 """ Returns a generator object of log messages. """ 277 chars = (c for c in (self._at(i) for i in self._range()) if c != 0) 278 line = bytearray() 279 for c in chars: 280 line.append(c) 281 if chr(c) == '\n': 282 yield line.decode(errors='backslashreplace') 283 line = bytearray() 284 yield line.decode(errors='backslashreplace') 285 286 def _at(self, i): 287 """ Returns a character at a given index. """ 288 err = lldb.SBError() 289 c = self._buffer.GetUnsignedInt8(err, i) 290 if not err.Success(): 291 raise ValueError( 292 "Failed to read character at offset " + str(i) + ": " + err.GetCString()) 293 return c 294 295 def _range(self): 296 """ Returns character indices starting at a ring buffer head. """ 297 start = int(self._msgbuf.msg_bufx) 298 size = int(self._msgbuf.msg_size) 299 return ((start + i) % size for i in range(0, size)) 300 301 302class LogQueue(object): 303 """ Represents a kernel log queue. """ 304 305 def __init__(self, cpu, lq): 306 self._cpu = cpu 307 self._lq = lq 308 309 @property 310 def cpu(self): 311 """ Returns a CPU number the log queue is associated with. """ 312 return self._cpu 313 314 @property 315 def ptr(self): 316 """ Returns a pointer to enclosed log_queue_s. """ 317 return self._lq 318 319 @property 320 def address(self): 321 """ Returns a log queue address. """ 322 return int(self.ptr) 323 324 @property 325 def size(self): 326 """ Returns an actual total log queue size. """ 327 slot_size = 1 << unsigned(self._lq.lq_mem_size_order) 328 return self._lq.lq_cnt_mem_active * slot_size 329 330 @property 331 def enqueued(self): 332 """ Returns a generator of logs enqueued in the log queue. """ 333 return self._lq_entries(addressof(self._lq.lq_log_list)) 334 335 @property 336 def dispatched(self): 337 """ Returns a generator of logs dispatched by the log queue. """ 338 return self._lq_entries(addressof(self._lq.lq_dispatch_list)) 339 340 @staticmethod 341 def _lq_entries(lqe_list): 342 """ Returns a generator of LQEntry elements representing given single-linked list. """ 343 def lq_entry(lqe): 344 lqe_state = GetEnumName('log_queue_entry_state_t', 345 lqe.lqe_state, 'LOG_QUEUE_ENTRY_STATE_') 346 return LQEntry(state=lqe_state, size=lqe.lqe_size, lmid=lqe.lqe_lm_id, data=lqe.lqe_payload) 347 return (lq_entry(e) for e in IterateTAILQ_HEAD(lqe_list, 'lqe_link', 's') if e) 348 349 @staticmethod 350 def collect(): 351 """ Returns a list of all per-CPU log queues. """ 352 pcpu_lqs = addressof(kern.GetGlobalVariable('percpu_slot_oslog_queue')) 353 pcpu_lqs_type = pcpu_lqs.GetSBValue().GetType().name 354 cpus = range(0, kern.globals.zpercpu_early_count) 355 356 def PCPUSlot(i): 357 addr = unsigned(pcpu_lqs) + kern.PERCPU_BASE(i) 358 return kern.GetValueFromAddress(addr, pcpu_lqs_type) 359 360 return [LogQueue(cpu, PCPUSlot(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.rstrip("\n")) 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