Grabserial

grabserial - grab serial port output

Introduction
grabserial is a small program which reads a serial port and writes the data to standard output. The main purpose of this tool is to collect messages written to the serial console from a target board running Linux, and save the messages on a host machine.

Download and Installation
Download grabserial from here: [[Media:grabserial]]

''Note: Due to MediaWiki stupidity, this file downloads with a leading upper-case letter. Please rename to lowercase on download (e.g. "mv Grabserial grabserial")''

To install, merely place 'grabserial' on the path. This would work: su root ; mv grabserial /usr/local/bin

grabserial requires the python "serial" module. This module is not shipped with most distributions of python by default. Here's a copy you can install if you don't have it. (You can check if you already have it by typing: 'python', then "import serial" in the interactive python interpreter.

[[Media:pyserial-2.2.zip]]

To install this, download the archive, unzip it, and following the installation instructions in pyserial-2.2/README.txt.

The latest Pyserial can be obtained from: The current version as of November 2008 is 2.4, which is newer than what I've got here.

Usage
The grabserial program is very simple, but it provides some useful extra features that make it more than a mere 'cat' program.

Use 'grabserial -h' to see online usage for the program.

You can specify the serial configuration options, including the Linux device node to use, and the port speed settings on the grabserial command line. If no options are specified, grabserial uses serial port /dev/ttyS0, at 115200 baud with "8, None and 1" (8N1) settings.

Normally, the program runs in an infinite loop, reading from the serial port and writing to standard out until it is interrupted by the user (usually by typing control-C). However, you can tell the program to stop after a certain amount of time. This is useful for including the script in automated test scenarios.

Also, you can tell the program to provide timing information for each line received. This is useful to measure the time it takes for events to happen on the target. A common thing to measure on a target running embedded Linux is bootup time. With grabserial, you can specify a pattern to match against the lines read from the serial port. When this pattern is seen, it sets a "base time", and all subsequent time values printed out will be relative to this base. Thus, you can customize the start time for the time measurements, to make it easier to see the duration of events in the system.

Usage Examples
Here are some examples of use:

grabserial

This will echo data seen on device /dev/ttyS0, until the user pressed ctrl-C.

grabserial -v -d "/dev/ttyUSB0" -b 115200 -w 8 -p N -s 1 -e 30 -t -m "Starting kernel.*"

This opens /dev/ttyUSB0, at baud rate 115200, and 8-bit chars, No parity and 1 stop bit. This will capture and display data for 30 seconds, putting a timestamp on each line received, and restarting the timestamp at 0 when a line containing "Kernel start" is seen. The '-v' makes grabserial verbose (printing some extra messages before starting.

If you want to use grabserial with minicom on the same serial port without conflict, for example to temporarily set a boot parameter or specify a different kernel image without changing the parameters in flash, you could follow this procedure:
 * Prepare the grabserial command in one window but don't hit enter.
 * Open minicom and set the bootloader environment, bootargs, etc. and tftp the kernel.
 * Use one bootloader command to delay a few seconds and boot. For u-boot this is done with something like: "sleep 5; bootm 0x80000000".
 * Immediately exit minicom and run grabserial. After the delay expires, grabserial measures boot output.

Sample Output
Here is sample output from grabserial. This shows the reboot of an ARM-based system (OMAP Starter Kit). Note that the U-Boot prompt appears at time 1.084614. The grabserial command specifies to restart the timestamps when "Starting kernel.*" is seen. This happens at time 11.557150 after grabserial was started.

Note that the first kernel message appears 3.14 seconds later. Actually, the kernel starts well before this, but it takes this long before the kernel to initialize the serial port and start emitting messages. You will notice that a bunch of messages come out in rapid succession. These are messages that were queued up during the boot, before the serial console was initialized.

[tbird@timdesk grabserial]$ ./grabserial -v -e 60 -t -m "Starting kernel.*" Opening serial port /dev/ttyS0 115200:8N1:xonxoff=0:rtcdtc=0 Program will end in 60 seconds Printing timing information for each line Matching pattern 'Starting kernel.*' to set base time Use Control-C to stop... [   0.000004] Killed [   0.080060] [    0.080268] [    0.080329] BusyBox v1.01 (2006.05.09-03:34+0000) Built-in shell (ash) [   0.088362] Enter 'help' for a list of built-in commands. [   0.093054] [    0.093136] ash: can't access tty; job control turned off [   0.096457] / # Restarting system. [   1.004806] . [    1.084345] [    1.084553] [    1.084614] U-Boot 1.1.4 (Sep  5 2006 - 17:59:15) [   1.089194] [    1.089263] CPU:   OMAP1611b at 96.0 MHz (DPLL1=96.0 MHz) [   1.093231] Board: OSK5912 [   1.096895] DRAM:  32 MB [    1.099982] Flash: 32 MB [    1.200071] In:    serial [   1.200677] Out:   serial [   1.201184] Err:   serial [   1.428094] Hit any key to stop autoboot:  4 ��� 3 ��� 2 ��� 1 ��� 0 [   5.428690] Using MAC Address 00:0E:99:02:06:83 [   5.432732] BOOTP broadcast 1 [   5.588358] DHCP client bound to address 192.168.2.74 [   5.593211] TFTP from server 192.168.2.1; our IP address is 192.168.2.74 [   5.600801] Filename 'osk4/boot/uImage.osk4'. [   5.602047] Load address: 0x10000000 [   5.605179] Loading: *�################################################################# [   6.520688] 	 ################################################################# [    7.420636] 	 ################################################################# [    8.309524] 	 ################################################################# [    9.205599] 	 ############################# [    9.608708] done [   9.613735] Bytes transferred = 1477696 (168c40 hex) [  10.144643] ## Booting image at 10000000 ... [  10.145944]    Image Name:   Linux-2.6.16.24-alp [  10.149553]    Image Type:   ARM Linux Kernel Image (uncompressed) [  10.153733]    Data Size:    1477632 Bytes =  1.4 MB [   10.158305]    Load Address: 10008000 [  10.161113]    Entry Point:  10008000 [  10.162053]    Verifying Checksum ... OK [  11.556790] OK [   11.557086] [  11.557150] Starting kernel ... [   0.004158] [    0.015515] Uncompressing Linux................................................................................................. done, booting the kernel. [   3.143765] Linux version 2.6.16.24-alp (tbird@timdesk.am.sony.com) (gcc version 3.4.4) #1 PREEMPT Wed Sep 6 14:16:46 PDT 2006 [   3.153071] CPU: ARM926EJ-Sid(wt) [41069263] revision 3 (ARMv5TEJ) [   3.159875] Machine: TI-OSK [   3.160508] Memory policy: ECC disabled, Data cache writethrough [   3.164693] OMAP1611b revision 2 handled as 16xx id: eb058f7948920b0d [   3.178089] SRAM: Mapped pa 0x20000000 to va 0xd0000000 size: 0x3f000 [   3.180327] CPU0: D VIVT write-back cache [   3.181426] CPU0: I cache: 16384 bytes, associativity 4, 32 byte lines, 128 sets [   3.184500] CPU0: D cache: 8192 bytes, associativity 4, 32 byte lines, 64 sets [   3.189360] Built 1 zonelists [   3.200389] Kernel command line: mem=32M console=ttyS0,115200n8 noinitrd ip=bootp root=/dev/nfs [   3.203340] Clocks: ARM_SYSST: 0x1000 DPLL_CTL: 0x2833 ARM_CKCTL: 0x2000 [   3.209108] Clocking rate (xtal/DPLL1/MPU): 12.0/192.0/192.0 MHz [   3.211017] Total of 128 interrupts in 4 interrupt banks [   3.213020] OMAP GPIO hardware version 1.0 [   3.216794] MUX: initialized M7_1610_GPIO62 [   3.220452] MUX: Setting register M7_1610_GPIO62 [   3.224991]       FUNC_MUX_CTRL_10 (0xfffe1098) = 0x00018000 -> 0x00018000 [   3.228452]       PULL_DWN_CTRL_4 (0xfffe10ac) = 0x00000000 -> 0x01000000 [   3.232948] PID hash table entries: 256 (order: 8, 4096 bytes) [   3.237881] OMAP MPU timers initialized [   3.241442] Console: colour dummy device 80x30 [   3.252541] Dentry cache hash table entries: 8192 (order: 3, 32768 bytes) [   3.254785] Inode-cache hash table entries: 4096 (order: 2, 16384 bytes) [   3.260600] Memory: 32MB = 32MB total [   3.261561] Memory: 29268KB available (2465K code, 534K data, 108K init) [   3.263737] Mount-cache hash table entries: 512 [   3.265025] CPU: Testing write buffer coherency: ok [    3.273364] NET: Registered protocol family 16 [   3.274672] MUX: Setting register N15_1610_MPUIO2 [   3.280363]       FUNC_MUX_CTRL_7 (0xfffe1020) = 0x00000000 -> 0x00000000 [   3.282539]       PU_PD_SEL_1 (0xfffe10b8) = 0x00000000 -> 0x00000000 [   3.287859]       PULL_DWN_CTRL_1 (0xfffe1044) = 0x00000000 -> 0x00000000 [   3.292311] OMAP DMA hardware version 1 [   3.296097] DMA capabilities: 000c0000:00000000:01ff:003f:007f [   3.301143] Initializing OMAP McBSP system [   3.302266] omap_dsp_init done [   3.304250] USB: hmc 16, usb0 2 wires [   3.307814] i2c_omap i2c_omap.1: bus 0 rev2.2 at 100 kHz [   3.309446] tps65010: version 2 May 2005 [   3.321770] MUX: initialized N14_1610_UWIRE_CS0 [   3.323110] MUX: Setting register N14_1610_UWIRE_CS0 [   3.328448]       FUNC_MUX_CTRL_8 (0xfffe1024) = 0x00001200 -> 0x00001200 [   3.330625]       PULL_DWN_CTRL_1 (0xfffe1044) = 0x00000000 -> 0x00200000 [   3.336881] MUX: initialized P15_1610_UWIRE_CS3 [   3.338189] MUX: Setting register P15_1610_UWIRE_CS3 [   3.339625]       FUNC_MUX_CTRL_8 (0xfffe1024) = 0x00001200 -> 0x00001200 [   3.346287]       PULL_DWN_CTRL_1 (0xfffe1044) = 0x00200000 -> 0x00600000 [   3.357323] SCSI subsystem initialized [   3.358316] usbcore: registered new driver usbfs [   3.359668] usbcore: registered new driver hub [   3.360912] MUX: initialized P18_1610_GPIO3 [   3.362060] MUX: Setting register P18_1610_GPIO3 [   3.364527]       FUNC_MUX_CTRL_7 (0xfffe1020) = 0x00000000 -> 0x00000000 [   3.369310]       PULL_DWN_CTRL_1 (0xfffe1044) = 0x00600000 -> 0x00600100 [   3.376092] MUX: Setting register MPUIO4 [   3.377174]       FUNC_MUX_CTRL_7 (0xfffe1020) = 0x00000000 -> 0x00000000 [   3.385256]       PULL_DWN_CTRL_1 (0xfffe1044) = 0x00600100 -> 0x00600100 [   3.389801] NetWinder Floating Point Emulator V0.97 (double precision) [   3.393302] OMAP OCPI interconnect driver loaded [   3.396960] squashfs: version 3.0 (2006/03/15) Phillip Lougher [   3.402174] Initializing Cryptographic API [   3.404791] io scheduler noop registered [   3.408466] io scheduler anticipatory registered (default) [   3.412313] io scheduler deadline registered [   3.413490] io scheduler cfq registered [   3.417385] omapfb: configured for panel osk [   3.420454] omapfb-lcdc: init [   3.421153] omapfb-lcdc: Pixel clock divider value is obsolete. [   3.425363] omapfb-lcdc: Try to set pixel_clock to 8000 and pcd to 0 in drivers/video/omap/lcd_osk.c and submit a patch. [   3.436613] MUX: initialized PWL [   3.437431] MUX: Setting register PWL [   3.440454]       FUNC_MUX_CTRL_6 (0xfffe101c) = 0x00000001 -> 0x00000009 [   3.445116]       PULL_DWN_CTRL_0 (0xfffe1040) = 0x00000000 -> 0x00000000 [   3.452227] Console: switching to colour frame buffer device 30x40 [   3.456534] omapfb: initialized vram=1048576 pixclock 8000 kHz hfreq 20.1 kHz vfreq 63.3 Hz [    3.465909] OMAP RTC Driver [   3.466547] omap_rtc: RTC already running. [   3.468086] Serial: 8250/16550 driver $Revision: 1.90 $ 4 ports, IRQ sharing disabled [   3.473121] serial8250.0: ttyS0 at MMIO map 0xfffb0000 mem 0xfefb0000 (irq = 46) is a ST16654 [   3.503986] loop: loaded (max 8 devices) [   3.507833] PPP generic driver version 2.4.2 [   3.515766] smc91x.c: v1.1, sep 22 2004 by Nicolas Pitre  [   3.523720] eth0: SMC91C94 (rev 9) at c280d300 IRQ 160 [nowait] [   3.528740] eth0: Ethernet addr: 00:0e:99:02:06:83 [   3.541218] i2c /dev entries driver [   3.542120] Uniform Multi-Platform E-IDE driver Revision: 7.00alpha2 [   3.547861] ide: Assuming 50MHz system bus speed for PIO modes; override with idebus=xx [   3.566463] omapflash.0: Found 1 x16 devices at 0x0 in 16-bit bank [   3.571704] omapflash.0: Found 1 x16 devices at 0x1000000 in 16-bit bank [   3.576652]  Intel/Sharp Extended Query Table at 0x0031 [   3.585172] Using buffer write method [   3.586158] cfi_cmdset_0001: Erase suspend on write enabled [   3.593080] Creating 4 MTD partitions on "omapflash.0": [   3.594590] 0x00000000-0x00020000 : "bootloader" [   3.599836] 0x00020000-0x00040000 : "params" [   3.612855] 0x00040000-0x00240000 : "kernel" [   3.619818] 0x00240000-0x02000000 : "filesystem" [   3.628784] MUX: initialized W11_1610_CF_CD1 [   3.637042] MUX: Setting register W11_1610_CF_CD1 [   3.638432]       FUNC_MUX_CTRL_10 (0xfffe1098) = 0x00018000 -> 0x00018000 [   3.645838]       PU_PD_SEL_3 (0xfffe10c0) = 0x00000000 -> 0x00000100 [   3.649130]       PULL_DWN_CTRL_3 (0xfffe104c) = 0x00000000 -> 0x00000000 [   3.653084] MUX: initialized P11_1610_CF_CD2 [   3.656692] MUX: Setting register P11_1610_CF_CD2 [   3.661153]       FUNC_MUX_CTRL_A (0xfffe102c) = 0x00000000 -> 0x18000000 [   3.667831]       PU_PD_SEL_2 (0xfffe10bc) = 0x0001f000 -> 0x0001f000 [   3.681167]       PULL_DWN_CTRL_2 (0xfffe1048) = 0x00800000 -> 0x00800000 [   3.683450] MUX: initialized R11_1610_CF_IOIS16 [   3.688351] MUX: Setting register R11_1610_CF_IOIS16 [   3.689816]       FUNC_MUX_CTRL_B (0xfffe1030) = 0x00000000 -> 0x00000003 [   3.692108]       PU_PD_SEL_2 (0xfffe10bc) = 0x0001f000 -> 0x0001f000 [   3.700708]       PULL_DWN_CTRL_2 (0xfffe1048) = 0x00800000 -> 0x00800000 [   3.702937] MUX: initialized V10_1610_CF_IREQ [   3.709578] MUX: Setting register V10_1610_CF_IREQ [   3.710966]       FUNC_MUX_CTRL_A (0xfffe102c) = 0x18000000 -> 0x1b000000 [   3.717225]       PULL_DWN_CTRL_2 (0xfffe1048) = 0x00800000 -> 0x00804000 [   3.720915] MUX: initialized W10_1610_CF_RESET [   3.728021] MUX: Setting register W10_1610_CF_RESET [   3.729576]       FUNC_MUX_CTRL_A (0xfffe102c) = 0x1b000000 -> 0x1b0c0000 [   3.737714]       PU_PD_SEL_2 (0xfffe10bc) = 0x0001f000 -> 0x0001f000 [   3.742789]       PULL_DWN_CTRL_2 (0xfffe1048) = 0x00804000 -> 0x00804000 [   3.746022] omap_cf: cs2 on irq 222 [   4.003884] usbmon: debugfs is not available [   4.011731] MUX: Setting register W8_1610_GPIO9 [   4.013045]       FUNC_MUX_CTRL_B (0xfffe1030) = 0x00000003 -> 0x00000003 [   4.020215]       PULL_DWN_CTRL_2 (0xfffe1048) = 0x00804000 -> 0x00804000 [   4.025198] MUX: initialized W4_USB_HIGHZ [   4.037645] MUX: Setting register W4_USB_HIGHZ [   4.038937]       FUNC_MUX_CTRL_D (0xfffe1038) = 0x00000020 -> 0x00000020 [   4.045310]       PULL_DWN_CTRL_3 (0xfffe104c) = 0x00000000 -> 0x00000020 [   4.047503] ohci ohci: OMAP OHCI [   4.048314] ohci ohci: new USB bus registered, assigned bus number 1 [   4.054055] ohci ohci: irq 38, io mem 0xfffba000 [   4.139829] usb usb1: configuration #1 chosen from 1 choice [   4.144109] hub 1-0:1.0: USB hub found [   4.148634] hub 1-0:1.0: 3 ports detected [   4.259850] Initializing USB Mass Storage driver... [   4.263752] usbcore: registered new driver usb-storage [   4.268446] USB Mass Storage support registered. [   4.275962] usbcore: registered new driver usbserial [   4.279808] /a/home/tbird/work/test/osk4/alp-linux/drivers/usb/serial/usb-serial.c: USB Serial support registered for generic [   4.295544] usbcore: registered new driver usbserial_generic [   4.300066] /a/home/tbird/work/test/osk4/alp-linux/drivers/usb/serial/usb-serial.c: USB Serial Driver core [   4.312019] /a/home/tbird/work/test/osk4/alp-linux/drivers/usb/serial/usb-serial.c: USB Serial support registered for pl2303 [   4.321894] usbcore: registered new driver pl2303 [   4.325398] /a/home/tbird/work/test/osk4/alp-linux/drivers/usb/serial/pl2303.c: Prolific PL2303 USB to serial adaptor driver [   4.337308] mice: PS/2 mouse device common for all mice [   4.340313] OMAP Keypad Driver [   4.343845] input: omap-keypad as /class/input/input0 [   4.356754] MUX: initialized P20_1610_GPIO4 [   4.368114] MUX: Setting register P20_1610_GPIO4 [   4.369580]       FUNC_MUX_CTRL_6 (0xfffe101c) = 0x00000009 -> 0x00000009 [   4.374978]       PULL_DWN_CTRL_1 (0xfffe1044) = 0x00600100 -> 0x00600180 [   4.377525] input: omap_ts as /class/input/input1 [   4.388732] OMAP touchscreen driver initialized [   4.390103] NET: Registered protocol family 2 [   4.487861] IP route cache hash table entries: 512 (order: -1, 2048 bytes) [   4.495774] TCP established hash table entries: 2048 (order: 1, 8192 bytes) [   4.503956] TCP bind hash table entries: 2048 (order: 1, 8192 bytes) [   4.508188] TCP: Hash tables configured (established 2048 bind 2048) [   4.521022] TCP reno registered [   4.521809] TCP bic registered [   4.522481] NET: Registered protocol family 1 [   4.523629] NET: Registered protocol family 17 [   5.039895] eth0: link up [    6.043939] Sending BOOTP requests. OK [   6.083956] IP-Config: Got BOOTP answer from 192.168.2.1, my address is 192.168.2.74 [   6.096524] IP-Config: Complete: [   6.097370]       device=eth0, addr=192.168.2.74, mask=255.255.255.0, gw=192.168.2.1, [   6.105211]      host=192.168.2.74, domain=, nis-domain=(none), [   6.121294]      bootserver=192.168.2.1, rootserver=192.168.2.1, rootpath=/target/osk4 [   6.123966] Looking up port of RPC 100003/2 on 192.168.2.1 [   6.148034] Looking up port of RPC 100005/1 on 192.168.2.1 [   6.192996] VFS: Mounted root (nfs filesystem). [   6.196374] Freeing init memory: 108K [   8.968141] Mounting devpts... [   9.100123] Starting syslogd... [   9.748191] Starting telnetd... [  10.000351] [   10.000530] [   10.000592] BusyBox v1.01 (2006.05.09-03:34+0000) Built-in shell (ash) [  10.008174] Enter 'help' for a list of built-in commands. [  10.012713] [   10.012893] ash: can't access tty; job control turned off [  10.044208] / #

Showing relative times
You can use the script 'show_delta' from the kernel 'scripts' directory to show relative times between lines. Just save the data to a file and then process with show_delta, like so:

grabserial -e 20 >/tmp/bootlog.txt ; linux_src/scripts/show_delta /tmp/bootlog.txt