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 254 def __eq__(self, other): 255 return unsigned(self._msgbuf) == unsigned(other._msgbuf) 256 257 def __hash__(self): 258 return hash(unsigned(self._msgbuf)) 259 260 @dyn_cached_property 261 def values(self, target=None): 262 """ Returns a list of all log messages. """ 263 264 return list(self._values()) 265 266 def __len__(self): 267 """ Returns a number of log messages in the message buffer. """ 268 return len(self.values) 269 270 def __getitem__(self, i): 271 """ Returns a log message at a given index. """ 272 return self.values[i] 273 274 def __iter__(self): 275 """ Returns an iterator object of log messages. """ 276 return iter(self.values) 277 278 def _values(self): 279 """ Returns a generator object of log messages. """ 280 chars = (c for c in (self._at(i) for i in self._range()) if c != 0) 281 line = bytearray() 282 for c in chars: 283 line.append(c) 284 if chr(c) == '\n': 285 yield six.ensure_str(line.decode('utf-8')) 286 line = bytearray() 287 yield six.ensure_str(line.decode('utf-8')) 288 289 def _at(self, i): 290 """ Returns a character at a given index. """ 291 err = lldb.SBError() 292 c = self._buffer.GetUnsignedInt8(err, i) 293 if not err.Success(): 294 raise ValueError( 295 "Failed to read character at offset " + str(i) + ": " + err.GetCString()) 296 return c 297 298 def _range(self): 299 """ Returns character indices starting at a ring buffer head. """ 300 start = int(self._msgbuf.msg_bufx) 301 size = int(self._msgbuf.msg_size) 302 return ((start + i) % size for i in range(0, size)) 303 304 305class LogQueue(object): 306 """ Represents a kernel log queue. """ 307 308 def __init__(self, cpu, lq): 309 self._cpu = cpu 310 self._lq = lq 311 312 @property 313 def cpu(self): 314 """ Returns a CPU number the log queue is associated with. """ 315 return self._cpu 316 317 @property 318 def ptr(self): 319 """ Returns a pointer to enclosed log_queue_s. """ 320 return self._lq 321 322 @property 323 def address(self): 324 """ Returns a log queue address. """ 325 return int(self.ptr) 326 327 @property 328 def size(self): 329 """ Returns an actual total log queue size. """ 330 slot_size = 1 << unsigned(self._lq.lq_mem_size_order) 331 return self._lq.lq_cnt_mem_active * slot_size 332 333 @property 334 def enqueued(self): 335 """ Returns a generator of logs enqueued in the log queue. """ 336 return self._lq_entries(addressof(self._lq.lq_log_list)) 337 338 @property 339 def dispatched(self): 340 """ Returns a generator of logs dispatched by the log queue. """ 341 return self._lq_entries(addressof(self._lq.lq_dispatch_list)) 342 343 @staticmethod 344 def _lq_entries(lqe_list): 345 """ Returns a generator of LQEntry elements representing given single-linked list. """ 346 def lq_entry(lqe): 347 lqe_state = GetEnumName('log_queue_entry_state_t', 348 lqe.lqe_state, 'LOG_QUEUE_ENTRY_STATE_') 349 return LQEntry(state=lqe_state, size=lqe.lqe_size, lmid=lqe.lqe_lm_id, data=lqe.lqe_payload) 350 return (lq_entry(e) for e in IterateTAILQ_HEAD(lqe_list, 'lqe_link', 's') if e) 351 352 @staticmethod 353 def collect(): 354 """ Returns a list of all per-CPU log queues. """ 355 pcpu_lqs = addressof(kern.GetGlobalVariable('percpu_slot_oslog_queue')) 356 cpus = range(0, kern.globals.zpercpu_early_count) 357 358 def PCPUSlot(pcpu_var, i): 359 addr = unsigned(pcpu_var) + kern.PERCPU_BASE(i) 360 return kern.GetValueFromAddress(addr, pcpu_var) 361 362 return [LogQueue(cpu, PCPUSlot(pcpu_lqs, cpu)) for cpu in cpus] 363 364 365def show_log_stream_logs(pp, logs): 366 """ Pretty prints logs metadata. 367 """ 368 hdr = "{0:>5s} {1:>7s} {2:>6s} {3:>12s} {4:>16s} {5:>8s} {6:>9s} {7:>7s} {8:>8s} {9:>18s}" 369 hdr_labels = ( 370 "BLOCK", "OFFSET", "LENGTH", "TIMESTAMP", "FTID", 371 "TID", "NAMESPACE", "TYPE", "CODE", "FLAGS" 372 ) 373 log_hdr = ( 374 "{log.blk_id:>5d} {log.offset:>7d} {ft.ft_length:>6d} {ts:>12d} " 375 "{ftid.value:>16x} {ft.ft_thread:>8d} {ftid.namespace[1]:>9s} " 376 "{ftid.type[1]:>7s} {ftid.code:>08x} {ftid.flags[1]:>18s}" 377 ) 378 379 log_count = 0 380 with pp.table(hdr.format(*hdr_labels)): 381 for log in logs: 382 pp.print(log_hdr.format(log=log, ts=log.lsm.lsm_ts, 383 ft=log.lsm.lsm_ft, ftid=log.ftid)) 384 log_count += 1 385 pp.print("(Shown {:d} logs)".format(log_count)) 386 387 388def show_log_stream_cache(pp, lsc): 389 """ Pretty prints configuration details of a given log cache. 390 """ 391 pp.header("Stream Cache") 392 393 pp.kvprint("Address", "{:#0x}", lsc.address) 394 pp.kvprint("Size", "{:>d} bytes ({:d} blocks)", 395 lsc.block_size(lsc.block_count), lsc.block_count) 396 pp.kvprint("Next Read Block", "{:d} (Offset: {:d})", 397 *lsc.block_position(lsc.cache_cursor)) 398 399 400def show_log_stream(pp, ls, read_pos): 401 """ Pretty prints configuration details of a given log stream. 402 """ 403 pp.header("Stream") 404 405 if not ls: 406 pp.print("No log stream configured.") 407 return 408 409 commited, logged_bytes = ls.logged 410 pp.kvprint("Address", "{:#0x}", ls.address) 411 pp.kvprint("State", "{:s}", "Enabled" if ls.enabled else "Disabled") 412 pp.kvprint("Size", "{:>d} bytes ({:d} blocks)", 413 ls.block_size(ls.block_count), ls.block_count) 414 pp.kvprint("Reserved", "{:d}", ls.reserved) 415 pp.kvprint("Commited", "{:d}", commited) 416 417 block, offset = ls.block_position(commited) 418 pp.kvprint("Written", "{:d} bytes", logged_bytes) 419 pp.kvprint("Next Write Block", "{:d} (Offset: {:d})", block, offset) 420 421 block, offset = ls.block_position(read_pos) 422 pp.kvprint("Read", "{:d} bytes", read_pos) 423 pp.kvprint("Next Read Block", "{:d} (Offset: {:d})", block, offset) 424 425 426def show_log_stream_stats(pp): 427 """ Pretty prints values of log stream counters. """ 428 pp.header("Statistics") 429 430 pp.kvprint("Total Count", "{:s}", 431 GetSimpleCounter(kern.globals.oslog_s_total_msgcount)) 432 pp.kvprint("Metadata Count", "{:s}", 433 GetSimpleCounter(kern.globals.oslog_s_metadata_msgcount)) 434 pp.kvprint("Streamed Logs", "{:s}", 435 GetSimpleCounter(kern.globals.oslog_s_streamed_msgcount)) 436 pp.kvprint("Dropped Logs", "{:s}", 437 GetSimpleCounter(kern.globals.oslog_s_dropped_msgcount)) 438 pp.kvprint("Invalid Logs", "{:s}", 439 GetSimpleCounter(kern.globals.oslog_s_error_count)) 440 441 442def show_log_stream_info(show_meta, O=None): 443 """ Pretty prints configuration details of OSLog Streaming and 444 its current content. 445 """ 446 pp = PPrinter(O) 447 log_cache = LogStreamCache(kern.globals.log_stream_cache) 448 449 pp.empty_line() 450 pp.header("Overview", True) 451 show_log_stream_stats(pp) 452 show_log_stream_cache(pp, log_cache) 453 show_log_stream(pp, log_cache.stream, log_cache.stream_cursor) 454 455 if not show_meta: 456 return 457 458 pp.empty_line() 459 pp.header("Cached Stream Logs", True) 460 show_log_stream_logs(pp, log_cache.logs(0)) 461 462 if log_cache.stream: 463 pp.empty_line() 464 pp.header("Stream Logs", True) 465 show_log_stream_logs( 466 pp, log_cache.stream.logs(log_cache.stream_cursor)) 467 468 469def show_log_queues(pp, log_queues, show_logs): 470 """ Pretty prints log queue summary and logs. """ 471 hdr = "{:>3s} {:>16s} {:>2s} {:>10s} {:>10s} {:>5s} {:>8s} {:>6s} {:>6s} {:>8s}" 472 hdr_labels = ( 473 "CPU", "ADDRESS", "ON", "STATE", "RECONF", "SLOTS", 474 "SIZE", "AVAIL", "STORED", "EN_ROUTE" 475 ) 476 hdr_lq = ( 477 "{cpu:>3s} {lq.address:>16x} {lq.ptr.lq_ready:>2d} {state:>10s} {reconf:>10s} " 478 "{lq.ptr.lq_cnt_mem_active:>5d} {size:>8d} {lq.ptr.lq_cnt_mem_avail:>6d} " 479 "{enq:>6d} {disp:>8d}" 480 ) 481 482 def show_log_queue(lq, enqueued, dispatched): 483 state = GetEnumName( 484 'lq_mem_state_t', lq._lq.lq_mem_state, 'LQ_MEM_STATE_') 485 reconf = GetEnumName( 486 'lq_req_state_t', lq._lq.lq_req_state, 'LQ_REQ_STATE_') 487 cpu = "N/A" if lq.cpu is None else str(lq.cpu) 488 pp.print(hdr_lq.format(lq=lq, state=state, size=lq.size, reconf=reconf, cpu=cpu, 489 enq=len(enqueued), 490 disp=len(dispatched))) 491 492 if show_logs: 493 for lq in log_queues: 494 lq_enqueued = list(lq.enqueued) 495 lq_dispatched = list(lq.dispatched) 496 pp.empty_line() 497 with pp.table(hdr.format(*hdr_labels)): 498 show_log_queue(lq, lq_enqueued, lq_dispatched) 499 500 pp.empty_line() 501 pp.header("Enqueues Log Messages") 502 show_log_queue_logs(pp, lq_enqueued) 503 504 pp.empty_line() 505 pp.header("Dispatched Log Messages") 506 show_log_queue_logs(pp, lq_dispatched) 507 508 pp.empty_line() 509 return 510 511 with pp.table(hdr.format(*hdr_labels)): 512 for lq in log_queues: 513 show_log_queue(lq, list(lq.enqueued), list(lq.dispatched)) 514 515 516def show_log_queue_logs(pp, lqe_list): 517 """ Pretty prints log queue logs. """ 518 if not lqe_list: 519 pp.print("No log messages present") 520 return 521 522 hdr = ("{:>5s} {:>7s} {:>10s} " 523 "{:>12s} {:>8s} " 524 "{:>16s} {:>9s} {:>7s} {:>8s} {:>18s}") 525 hdr_labels = ( 526 "LM_ID", "LM_SIZE", "STATE", "TIMESTAMP", "LOG_SIZE", 527 "FTID", "NAMESPACE", "TYPE", "CODE", "FLAGS" 528 ) 529 log_hdr = ( 530 "{lqe.lmid:>5x} {lqe.size:>7d} {lqe.state:>10s} " 531 "{d.lp_timestamp:>12d} {d.lp_data_size:>8d} " 532 "{ftid.value:>16x} {ftid.namespace[1]:>9s} " 533 "{ftid.type[1]:>7s} {ftid.code:>08x} {ftid.flags[1]:>18s}" 534 ) 535 with pp.table(hdr.format(*hdr_labels)): 536 for lqe in lqe_list: 537 pp.print(log_hdr.format(lqe=lqe, d=lqe.data, 538 ftid=FTID(lqe.data.lp_ftid))) 539 pp.print("(Shown {:d} logs)".format(len(lqe_list))) 540 541 542@lldb_command('showlogstream', 'L', fancy=True) 543def showLogStream(cmd_args=None, cmd_options=None, O=None): 544 """ Displays the contents of the log stream and the log stream cache. 545 546 showlogstream [-L] 547 548 Options: 549 -L: Show metadata of logs stored in the log stream and the cache 550 """ 551 552 show_meta = "-L" in cmd_options 553 554 show_log_stream_info(show_meta, O) 555 556 557@lldb_command('showlq', 'LC:A:', fancy=True) 558def showLogQueue(cmd_args=None, cmd_options=None, O=None): 559 """ Displays the contents of the log queue. 560 561 usage: showlq [-C cpu_num][-A addr][-L] 562 563 -C n Shows a log queue summary of a selected CPU. 564 -A a Shows a log queue summary at a given address. 565 -L Show metadata of enqueued and dispatched logs 566 567 Options -A and -C are mutually exclusive. 568 If no options provided summaries of all per-CPU log queues are shown. 569 570 Examples: 571 showlq 572 showlq -C 2 -L 573 showlq -A 0xfffffff123456789 -L 574 """ 575 576 log_queues = LogQueue.collect() 577 578 if "-C" in cmd_options and "-A" in cmd_options: 579 raise ArgumentError("Options -A and -C are mutually exclusive.") 580 581 if "-C" in cmd_options: 582 cpu_no = ArgumentStringToInt(cmd_options['-C']) 583 if cpu_no not in range(0, len(log_queues)): 584 print("CPU number out of [0, {:d}) range".format(len(log_queues))) 585 return 586 log_queues = [lq for lq in log_queues if lq.cpu == cpu_no] 587 elif "-A" in cmd_options: 588 addr = ArgumentStringToInt(cmd_options['-A']) 589 log_queues = [lq for lq in log_queues if addr == lq.address] 590 if not log_queues: 591 lq = kern.GetValueFromAddress(addr, 'log_queue_t') 592 log_queues = [LogQueue(None, lq)] 593 594 show_logs = "-L" in cmd_options 595 596 show_log_queues(PPrinter(O), log_queues, show_logs) 597 598 599@lldb_command('showmsgbuf', 'C:F') 600def showMsgBuf(cmd_args=None, cmd_options=None): 601 """ Displays the contents of msgbuf_t type at a given address. 602 603 usage: showmsgbuf [-C <num>][-F] addr 604 605 -C <num> Shows first or last (if negative) specified number of logs. 606 -F Show the content even if the magic key indicates data corruption. 607 """ 608 609 if not cmd_args: 610 print(showMsgBuf.__doc__) 611 return 612 613 addr = kern.GetValueFromAddress(cmd_args[0], 'struct msgbuf *') 614 615 if addr.msg_magic != MsgBuffer.MSG_MAGIC: 616 print("Error: Invalid msgbuf_t magic key {:#x} (expected {:#x}). " 617 "Invalid address or the content is corrupted.".format(addr.msg_magic, MsgBuffer.MSG_MAGIC)) 618 if not "-F" in cmd_options: 619 return 620 621 msgbuf = MsgBuffer(addr) 622 623 if "-C" in cmd_options: 624 count = ArgumentStringToInt(cmd_options['-C']) 625 n = min(abs(count), len(msgbuf)) 626 msgbuf = msgbuf[:n] if count > 0 else msgbuf[-n:] 627 628 for msg in msgbuf: 629 print(msg.rstrip("\n")) 630 631 632@lldb_command('systemlog', 'C:F') 633def systemLog(cmd_args=None, cmd_options=None): 634 """ Displays the contents of the system message buffer. 635 636 usage: systemlog [-C <num>][-F] 637 638 -C <num> Shows first or last (if negative) specified number of logs. 639 -F Show the content even if the magic key indicates data corruption. 640 """ 641 showMsgBuf([unsigned(kern.globals.msgbufp)], cmd_options) 642