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(LogStream, self).__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(LogStreamCache, self).__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() 283 line = bytearray() 284 yield line.decode() 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 cpus = range(0, kern.globals.zpercpu_early_count) 354 355 def PCPUSlot(pcpu_var, i): 356 addr = unsigned(pcpu_var) + kern.PERCPU_BASE(i) 357 return kern.GetValueFromAddress(addr, pcpu_var) 358 359 return [LogQueue(cpu, PCPUSlot(pcpu_lqs, cpu)) for cpu in cpus] 360 361 362def show_log_stream_logs(pp, logs): 363 """ Pretty prints logs metadata. 364 """ 365 hdr = "{0:>5s} {1:>7s} {2:>6s} {3:>12s} {4:>16s} {5:>8s} {6:>9s} {7:>7s} {8:>8s} {9:>18s}" 366 hdr_labels = ( 367 "BLOCK", "OFFSET", "LENGTH", "TIMESTAMP", "FTID", 368 "TID", "NAMESPACE", "TYPE", "CODE", "FLAGS" 369 ) 370 log_hdr = ( 371 "{log.blk_id:>5d} {log.offset:>7d} {ft.ft_length:>6d} {ts:>12d} " 372 "{ftid.value:>16x} {ft.ft_thread:>8d} {ftid.namespace[1]:>9s} " 373 "{ftid.type[1]:>7s} {ftid.code:>08x} {ftid.flags[1]:>18s}" 374 ) 375 376 log_count = 0 377 with pp.table(hdr.format(*hdr_labels)): 378 for log in logs: 379 pp.print(log_hdr.format(log=log, ts=log.lsm.lsm_ts, 380 ft=log.lsm.lsm_ft, ftid=log.ftid)) 381 log_count += 1 382 pp.print("(Shown {:d} logs)".format(log_count)) 383 384 385def show_log_stream_cache(pp, lsc): 386 """ Pretty prints configuration details of a given log cache. 387 """ 388 pp.header("Stream Cache") 389 390 pp.kvprint("Address", "{:#0x}", lsc.address) 391 pp.kvprint("Size", "{:>d} bytes ({:d} blocks)", 392 lsc.block_size(lsc.block_count), lsc.block_count) 393 pp.kvprint("Next Read Block", "{:d} (Offset: {:d})", 394 *lsc.block_position(lsc.cache_cursor)) 395 396 397def show_log_stream(pp, ls, read_pos): 398 """ Pretty prints configuration details of a given log stream. 399 """ 400 pp.header("Stream") 401 402 if not ls: 403 pp.print("No log stream configured.") 404 return 405 406 commited, logged_bytes = ls.logged 407 pp.kvprint("Address", "{:#0x}", ls.address) 408 pp.kvprint("State", "{:s}", "Enabled" if ls.enabled else "Disabled") 409 pp.kvprint("Size", "{:>d} bytes ({:d} blocks)", 410 ls.block_size(ls.block_count), ls.block_count) 411 pp.kvprint("Reserved", "{:d}", ls.reserved) 412 pp.kvprint("Commited", "{:d}", commited) 413 414 block, offset = ls.block_position(commited) 415 pp.kvprint("Written", "{:d} bytes", logged_bytes) 416 pp.kvprint("Next Write Block", "{:d} (Offset: {:d})", block, offset) 417 418 block, offset = ls.block_position(read_pos) 419 pp.kvprint("Read", "{:d} bytes", read_pos) 420 pp.kvprint("Next Read Block", "{:d} (Offset: {:d})", block, offset) 421 422 423def show_log_stream_stats(pp): 424 """ Pretty prints values of log stream counters. """ 425 pp.header("Statistics") 426 427 pp.kvprint("Total Count", "{:s}", 428 GetSimpleCounter(kern.globals.oslog_s_total_msgcount)) 429 pp.kvprint("Metadata Count", "{:s}", 430 GetSimpleCounter(kern.globals.oslog_s_metadata_msgcount)) 431 pp.kvprint("Streamed Logs", "{:s}", 432 GetSimpleCounter(kern.globals.oslog_s_streamed_msgcount)) 433 pp.kvprint("Dropped Logs", "{:s}", 434 GetSimpleCounter(kern.globals.oslog_s_dropped_msgcount)) 435 pp.kvprint("Invalid Logs", "{:s}", 436 GetSimpleCounter(kern.globals.oslog_s_error_count)) 437 438 439def show_log_stream_info(show_meta, O=None): 440 """ Pretty prints configuration details of OSLog Streaming and 441 its current content. 442 """ 443 pp = PPrinter(O) 444 log_cache = LogStreamCache(kern.globals.log_stream_cache) 445 446 pp.empty_line() 447 pp.header("Overview", True) 448 show_log_stream_stats(pp) 449 show_log_stream_cache(pp, log_cache) 450 show_log_stream(pp, log_cache.stream, log_cache.stream_cursor) 451 452 if not show_meta: 453 return 454 455 pp.empty_line() 456 pp.header("Cached Stream Logs", True) 457 show_log_stream_logs(pp, log_cache.logs(0)) 458 459 if log_cache.stream: 460 pp.empty_line() 461 pp.header("Stream Logs", True) 462 show_log_stream_logs( 463 pp, log_cache.stream.logs(log_cache.stream_cursor)) 464 465 466def show_log_queues(pp, log_queues, show_logs): 467 """ Pretty prints log queue summary and logs. """ 468 hdr = "{:>3s} {:>16s} {:>2s} {:>10s} {:>10s} {:>5s} {:>8s} {:>6s} {:>6s} {:>8s}" 469 hdr_labels = ( 470 "CPU", "ADDRESS", "ON", "STATE", "RECONF", "SLOTS", 471 "SIZE", "AVAIL", "STORED", "EN_ROUTE" 472 ) 473 hdr_lq = ( 474 "{cpu:>3s} {lq.address:>16x} {lq.ptr.lq_ready:>2d} {state:>10s} {reconf:>10s} " 475 "{lq.ptr.lq_cnt_mem_active:>5d} {size:>8d} {lq.ptr.lq_cnt_mem_avail:>6d} " 476 "{enq:>6d} {disp:>8d}" 477 ) 478 479 def show_log_queue(lq, enqueued, dispatched): 480 state = GetEnumName( 481 'lq_mem_state_t', lq._lq.lq_mem_state, 'LQ_MEM_STATE_') 482 reconf = GetEnumName( 483 'lq_req_state_t', lq._lq.lq_req_state, 'LQ_REQ_STATE_') 484 cpu = "N/A" if lq.cpu is None else str(lq.cpu) 485 pp.print(hdr_lq.format(lq=lq, state=state, size=lq.size, reconf=reconf, cpu=cpu, 486 enq=len(enqueued), 487 disp=len(dispatched))) 488 489 if show_logs: 490 for lq in log_queues: 491 lq_enqueued = list(lq.enqueued) 492 lq_dispatched = list(lq.dispatched) 493 pp.empty_line() 494 with pp.table(hdr.format(*hdr_labels)): 495 show_log_queue(lq, lq_enqueued, lq_dispatched) 496 497 pp.empty_line() 498 pp.header("Enqueues Log Messages") 499 show_log_queue_logs(pp, lq_enqueued) 500 501 pp.empty_line() 502 pp.header("Dispatched Log Messages") 503 show_log_queue_logs(pp, lq_dispatched) 504 505 pp.empty_line() 506 return 507 508 with pp.table(hdr.format(*hdr_labels)): 509 for lq in log_queues: 510 show_log_queue(lq, list(lq.enqueued), list(lq.dispatched)) 511 512 513def show_log_queue_logs(pp, lqe_list): 514 """ Pretty prints log queue logs. """ 515 if not lqe_list: 516 pp.print("No log messages present") 517 return 518 519 hdr = ("{:>5s} {:>7s} {:>10s} " 520 "{:>12s} {:>8s} " 521 "{:>16s} {:>9s} {:>7s} {:>8s} {:>18s}") 522 hdr_labels = ( 523 "LM_ID", "LM_SIZE", "STATE", "TIMESTAMP", "LOG_SIZE", 524 "FTID", "NAMESPACE", "TYPE", "CODE", "FLAGS" 525 ) 526 log_hdr = ( 527 "{lqe.lmid:>5x} {lqe.size:>7d} {lqe.state:>10s} " 528 "{d.lp_timestamp:>12d} {d.lp_data_size:>8d} " 529 "{ftid.value:>16x} {ftid.namespace[1]:>9s} " 530 "{ftid.type[1]:>7s} {ftid.code:>08x} {ftid.flags[1]:>18s}" 531 ) 532 with pp.table(hdr.format(*hdr_labels)): 533 for lqe in lqe_list: 534 pp.print(log_hdr.format(lqe=lqe, d=lqe.data, 535 ftid=FTID(lqe.data.lp_ftid))) 536 pp.print("(Shown {:d} logs)".format(len(lqe_list))) 537 538 539@lldb_command('showlogstream', 'L', fancy=True) 540def showLogStream(cmd_args=None, cmd_options=None, O=None): 541 """ Displays the contents of the log stream and the log stream cache. 542 543 showlogstream [-L] 544 545 Options: 546 -L: Show metadata of logs stored in the log stream and the cache 547 """ 548 549 show_meta = "-L" in cmd_options 550 551 show_log_stream_info(show_meta, O) 552 553 554@lldb_command('showlq', 'LC:A:', fancy=True) 555def showLogQueue(cmd_args=None, cmd_options=None, O=None): 556 """ Displays the contents of the log queue. 557 558 usage: showlq [-C cpu_num][-A addr][-L] 559 560 -C n Shows a log queue summary of a selected CPU. 561 -A a Shows a log queue summary at a given address. 562 -L Show metadata of enqueued and dispatched logs 563 564 Options -A and -C are mutually exclusive. 565 If no options provided summaries of all per-CPU log queues are shown. 566 567 Examples: 568 showlq 569 showlq -C 2 -L 570 showlq -A 0xfffffff123456789 -L 571 """ 572 573 log_queues = LogQueue.collect() 574 575 if "-C" in cmd_options and "-A" in cmd_options: 576 raise ArgumentError("Options -A and -C are mutually exclusive.") 577 578 if "-C" in cmd_options: 579 cpu_no = ArgumentStringToInt(cmd_options['-C']) 580 if cpu_no not in range(0, len(log_queues)): 581 print("CPU number out of [0, {:d}) range".format(len(log_queues))) 582 return 583 log_queues = [lq for lq in log_queues if lq.cpu == cpu_no] 584 elif "-A" in cmd_options: 585 addr = ArgumentStringToInt(cmd_options['-A']) 586 log_queues = [lq for lq in log_queues if addr == lq.address] 587 if not log_queues: 588 lq = kern.GetValueFromAddress(addr, 'log_queue_t') 589 log_queues = [LogQueue(None, lq)] 590 591 show_logs = "-L" in cmd_options 592 593 show_log_queues(PPrinter(O), log_queues, show_logs) 594 595 596@lldb_command('showmsgbuf', 'C:F') 597def showMsgBuf(cmd_args=None, cmd_options=None): 598 """ Displays the contents of msgbuf_t type at a given address. 599 600 usage: showmsgbuf [-C <num>][-F] addr 601 602 -C <num> Shows first or last (if negative) specified number of logs. 603 -F Show the content even if the magic key indicates data corruption. 604 """ 605 606 if not cmd_args: 607 print(showMsgBuf.__doc__) 608 return 609 610 addr = kern.GetValueFromAddress(cmd_args[0], 'struct msgbuf *') 611 612 if addr.msg_magic != MsgBuffer.MSG_MAGIC: 613 print("Error: Invalid msgbuf_t magic key {:#x} (expected {:#x}). " 614 "Invalid address or the content is corrupted.".format(addr.msg_magic, MsgBuffer.MSG_MAGIC)) 615 if not "-F" in cmd_options: 616 return 617 618 msgbuf = MsgBuffer(addr) 619 620 if "-C" in cmd_options: 621 count = ArgumentStringToInt(cmd_options['-C']) 622 n = min(abs(count), len(msgbuf)) 623 msgbuf = msgbuf[:n] if count > 0 else msgbuf[-n:] 624 625 for msg in msgbuf: 626 print(msg.rstrip("\n")) 627 628 629@lldb_command('systemlog', 'C:F') 630def systemLog(cmd_args=None, cmd_options=None): 631 """ Displays the contents of the system message buffer. 632 633 usage: systemlog [-C <num>][-F] 634 635 -C <num> Shows first or last (if negative) specified number of logs. 636 -F Show the content even if the magic key indicates data corruption. 637 """ 638 showMsgBuf([unsigned(kern.globals.msgbufp)], cmd_options) 639