post 3.14 serial regression

post 3.14 serial regression

[Dave Hansen]

Hi Geert,

I have a piece of hardware where the two normal serial ports are
inaccessible and buried inside the system somewhere.  I put a PCIe
serial port card in which is normally detected as a ST16650V2:

[   17.939057] 0000:13:00.0: ttyS2 at I/O 0x1008 (irq = 18, base_baud =
115200) is a ST16650V2

I normally boot with both a console= and earlyprintk=.  Since the card
is at a non-standard I/O port, I have to use the I/O port directly in
the earlyprintk arguments instead of ttySXX:

	console=ttyS2,115200 earlyprintk=serial,0x1008,115200

However, after 3.14, commit 5f5c9ae56c3:

> commit 5f5c9ae56c38942623f69c3e6dc6ec78e4da2076
> Author: Geert Uytterhoeven <geert+renesas@linux-m68k.org>
> Date:   Fri Feb 28 14:21:32 2014 +0100
> 
>     serial_core: Unregister console in uart_remove_one_port()

the system to appears to hang at boot:

...
> [    0.000000] NR_IRQS:16640 nr_irqs:2728 16
> [    0.000000] Console: colour VGA+ 80x25
> [    0.000000] console [ttyS2] enabled
> [    0.000000] bootconsole [earlyser0] disabled

Here's a boot with earlyprintk=...,keep so that I can get *some* output:

	http://sr71.net/~dave/intel/pre-3.15-console-dead.txt

At the end, you can see that init is somehow dying.  If I revert this
patch, init is happy again and doesn't die, and the serial console works
like before.  Could init somehow be angry that its console is gone or
broken somehow?  Also, if I boot without console=ttyS2,115200, the
system boots happily.

Here's the .config:

	http://sr71.net/~dave/intel/pre-3.15-console-dead.config.txt

Re: post 3.14 serial regression

[One Thousand Gnomes]

> At the end, you can see that init is somehow dying.  If I revert this
> patch, init is happy again and doesn't die, and the serial console works
> like before.

Can you check if init is getting a SIGHUP - possibly its opening the
device and when it goes away gets a hangup which it isn't catching ?

Alan

Re: post 3.14 serial regression

[Dave Hansen]

On 04/08/2014 04:27 AM, One Thousand Gnomes wrote:
>> At the end, you can see that init is somehow dying.  If I revert this
>> patch, init is happy again and doesn't die, and the serial console works
>> like before.
> 
> Can you check if init is getting a SIGHUP - possibly its opening the
> device and when it goes away gets a hangup which it isn't catching ?

I do see plenty of SIGCHLDs and a heap of SIGTERMs to 'systemd-udevd',
but no SIGHUP.  I do see a "Warning: unable to open an initial console."
now, though.  (details far below)

I instrumented uart_remove_one_port().  It *looks* like while searching
for a uart_port for 0x1008 (my actual port),
serial8250_find_match_or_unused() finds 0x3e8 since 0x3e8 is
PORT_UNKNOWN.  The new code unregisters the 0x1008 console since it
_thinks_ it is about to re-register it.

> [   18.280937] uart_remove_one_port() uport: ffffffff828c8020 uart_console(uport): 1 iobase: 3e8 membase:           (null)
> [   18.291970] CPU: 12 PID: 1 Comm: swapper/0 Not tainted 3.14.0-rc4+ #301
> [   18.298681] Hardware name: FUJITSU-SV PRIMEQUEST 1800E2/SB, BIOS PRIMEQUEST 1000 Series BIOS Version 1.24 09/14/2011
> [   18.309438]  ffffffff828c8020 ffff881ff2c2b9f8 ffffffff816ca8b5 0000000000000006
> [   18.316941]  ffff88fff1698730 ffff881ff2c2ba28 ffffffff813c759b ffffffff828c8020
> [   18.324452]  00000000ffffffe4 ffff881ff2c2ba88 ffffffff81cddf20 ffff881ff2c2ba58
> [   18.331962] Call Trace:
> [   18.334447]  [<ffffffff816ca8b5>] dump_stack+0x4e/0x68
> [   18.339665]  [<ffffffff813c759b>] uart_remove_one_port+0x12b/0x1b0
> [   18.345935]  [<ffffffff813cb2af>] serial8250_register_8250_port+0xbf/0x3c0
> [   18.352915]  [<ffffffff813ce105>] pciserial_init_ports+0x105/0x200
> [   18.359184]  [<ffffffff813ce2c9>] pciserial_init_one+0xc9/0x1e0
> [   18.365198]  [<ffffffff8135cd1d>] local_pci_probe+0x2d/0x80
> [   18.370849]  [<ffffffff8135d549>] pci_device_probe+0xe9/0x130
> [   18.376686]  [<ffffffff813df4e9>] driver_probe_device+0x89/0x390
> [   18.382778]  [<ffffffff813df89b>] __driver_attach+0xab/0xb0
> [   18.388434]  [<ffffffff813df7f0>] ? driver_probe_device+0x390/0x390
> [   18.394795]  [<ffffffff813dd57e>] bus_for_each_dev+0x5e/0x90
> [   18.400539]  [<ffffffff813df1ee>] driver_attach+0x1e/0x20
> [   18.406016]  [<ffffffff813ddfc7>] bus_add_driver+0x127/0x250
> [   18.411764]  [<ffffffff81d63bda>] ? early_serial_setup+0x138/0x138
> [   18.418032]  [<ffffffff813dfcf4>] driver_register+0x64/0xf0
> [   18.423687]  [<ffffffff81d63bda>] ? early_serial_setup+0x138/0x138
> [   18.429963]  [<ffffffff8135d2c4>] __pci_register_driver+0x64/0x70
> [   18.436146]  [<ffffffff81d62f1b>] ? sysrq_always_enabled_setup+0x20/0x20
> [   18.442954]  [<ffffffff81d63bf3>] serial_pci_driver_init+0x19/0x1b
> [   18.449227]  [<ffffffff81d25f7e>] do_one_initcall+0x9e/0x133
> [   18.454967]  [<ffffffff81d26119>] kernel_init_freeable+0x106/0x19a
> [   18.461241]  [<ffffffff81d258af>] ? do_early_param+0x86/0x86
> [   18.466989]  [<ffffffff816bc090>] ? rest_init+0xe0/0xe0
> [   18.472285]  [<ffffffff816bc09e>] kernel_init+0xe/0xf0
> [   18.477503]  [<ffffffff816d58fc>] ret_from_fork+0x7c/0xb0
> [   18.482978]  [<ffffffff816bc090>] ? rest_init+0xe0/0xe0
> [   18.488277] console [ttyS2] disabled

The last, desperate attempt in serial8250_find_match_or_unused() appears
to incorrectly hone in on my early printk port.  But, even if I comment
it out, I still can't boot.  The only way that work is to revert that patch.

> [   74.281757] TCP: cubic registered
> [   74.284954] NET: Registered protocol family 17
> [   74.301226] registered taskstats version 1
> [   74.311464] console [netcon0] enabled
> [   74.315018] netconsole: network logging started
> [   74.319612] /home/davehans/linux.git/drivers/rtc/hctosys.c: unable to open rtc device (rtc0)
> [   74.429357] Warning: unable to open an initial console.
> [   74.455233] Freeing unused kernel memory: 1200K (ffffffff81d10000 - ffffffff81e3c000)
> [   74.463028] Write protecting the kernel read-only data: 12288k
> [   74.503540] Freeing unused kernel memory: 1168K (ffff8800016dc000 - ffff880001800000)
> [   74.528592] Freeing unused kernel memory: 1556K (ffff880001a7b000 - ffff880001c00000)
> [   74.531566] input: AT Raw Set 2 keyboard as /devices/platform/i8042/serio0/input/input0
> [   74.581041] __send_signal(17, ffff883ff18d1df8, ffff881ff2c30000 / 'init', 1, 0)
> [   74.588753] __send_signal(17, ffff885ff1e87df8, ffff881ff2c30000 / 'init', 1, 0)
> [   74.592402] __send_signal(17, ffff887ff18b7df8, ffff881ff2c30000 / 'init', 1, 0)
> [   74.599975] __send_signal(17, ffff889ff1f45df8, ffff881ff2c30000 / 'init', 1, 0)
> [   74.611401] __send_signal(17, ffff88bff1959df8, ffff881ff2c30000 / 'init', 1, 0)
> [   74.619939] __send_signal(17, ffff88dff1f75df8, ffff881ff2c30000 / 'init', 1, 0)
> [   74.600332] __send_signal(17, ffff88fff11dddf8, ffff881ff2c30000 / 'init', 1, 0)
> [   74.608839] __send_signal(17, ffff881ff10f7df8, ffff881ff2c30000 / 'init', 1, 0)
> [   74.651958] __send_signal(17, ffff883ff190bdf8, ffff881ff2c30000 / 'init', 1, 0)
> [   74.659443] __send_signal(17, ffff885ff1e87df8, ffff881ff2c30000 / 'init', 1, 0)
> [   74.663930] __send_signal(17, ffff887ff18b7df8, ffff881ff2c30000 / 'init', 1, 0)
> [   74.672501] __send_signal(17, ffff889ff1f45df8, ffff881ff2c30000 / 'init', 1, 0)
> [   74.682406] __send_signal(17, ffff88bff1959df8, ffff881ff2c30000 / 'init', 1, 0)
> [   74.689887] __send_signal(17, ffff88dff1f75df8, ffff881ff2c30000 / 'init', 1, 0)
> [   74.671456] __send_signal(17, ffff88fff11dddf8, ffff881ff2c30000 / 'init', 1, 0)
> [   74.679483] __send_signal(17, ffff881ff111bdf8, ffff881ff2c30000 / 'init', 1, 0)
> [   74.720648] __send_signal(17, ffff881ff1139df8, ffff881ff2c30000 / 'init', 1, 0)
> [   74.730058] __send_signal(17, ffff885ff1f11df8, ffff883ff22910f0 / 'all_generic_ide', 1, 0)
> [   74.738516] __send_signal(17, ffff883ff1923df8, ffff881ff2c30000 / 'init', 1, 0)
> [   74.742990] __send_signal(17, ffff889ff1f45df8, ffff887ff1f110f0 / 'blacklist', 1, 0)
> [   74.750942] __send_signal(17, ffff887ff18e5df8, ffff881ff2c30000 / 'init', 1, 0)
> [   74.765067] __send_signal(17, ffff88dff1f75df8, ffff88bff36d43c0 / 'udev', 1, 0)
> [   74.737987] systemd-udevd[886]: starting version 204
> [   74.843940] scsi 4:0:0:0: CD-ROM            TEAC     DV-W28S-W        J.0A PQ: 0 ANSI: 0
> [   74.856780] sr0: scsi3-mmc drive: 24x/24x writer dvd-ram cd/rw xa/form2 cdda tray
> [   74.864226] cdrom: Uniform CD-ROM driver Revision: 3.20
> [   74.870897] sr 4:0:0:0: Attached scsi CD-ROM sr0
> [   74.876105] sr 4:0:0:0: Attached scsi generic sg1 type 5
> [   75.268518] __send_signal(17, ffff887ff1a99df8, ffff881ff1190000 / 'systemd-udevd', 1, 0)
> [   75.924745] __send_signal(17, ffff88fff1265df8, ffff88bff36d43c0 / 'udev', 1, 0)
> [   75.932409] __send_signal(17, ffff88bff19afdf8, ffff881ff2c30000 / 'init', 1, 0)
> [   75.936045] __send_signal(17, ffff887ff2741df8, ffff881ff2c30000 / 'init', 1, 0)
> [   75.942735] __send_signal(17, ffff887ff2237df8, ffff881ff2c30000 / 'init', 1, 0)
> [   75.951754] __send_signal(17, ffff889ff25ffdf8, ffff881ff2c30000 / 'init', 1, 0)
> [   75.960633] __send_signal(17, ffff889ff2533df8, ffff881ff2c30000 / 'init', 1, 0)
> [   75.969671] __send_signal(17, ffff88bff19afdf8, ffff881ff2c30000 / 'init', 1, 0)
> [   75.976364] __send_signal(17, ffff88bff226fdf8, ffff881ff2c30000 / 'init', 1, 0)
> [   75.985163] __send_signal(17, ffff88dff26b7df8, ffff881ff2c30000 / 'init', 1, 0)
> [   75.964610] __send_signal(17, ffff88dff1f75df8, ffff881ff2c30000 / 'init', 1, 0)
> [   75.982484] __send_signal(17, ffff88fff1265df8, ffff881ff2c30000 / 'init', 1, 0)
> [   76.026264] __send_signal(17, ffff883ff19b5df8, ffff881feeade5a0 / 'fixrtc', 1, 0)
> [   76.034015] __send_signal(17, ffff881fee077df8, ffff881ff2c30000 / 'init', 1, 0)
> [   76.037845] __send_signal(17, ffff885ff25cfdf8, ffff881ff2c30000 / 'init', 1, 0)
> [   76.061528] __send_signal(17, ffff88bff27c7df8, ffff889ff1d3a1e0 / 'resume', 1, 0)
> [   76.069223] __send_signal(17, ffff889ff25ffdf8, ffff881ff2c30000 / 'init', 1, 0)
> [   76.074561] __send_signal(17, ffff887ff2237df8, ffff881ff2c30000 / 'init', 1, 0)
> [   76.128750] EXT4-fs (sda1): mounted filesystem with ordered data mode. Opts: (null)
> [   76.136470] __send_signal(17, ffff889ff2533df8, ffff881ff2c30000 / 'init', 1, 0)
> [   76.147712] __send_signal(17, ffff88bff1abbdf8, ffff881ff2c30000 / 'init', 1, 0)
> [   76.155851] __send_signal(17, ffff88dff2dc7df8, ffff881ff2c30000 / 'init', 1, 0)
> [   76.135300] __send_signal(17, ffff88dff2dcddf8, ffff881ff2c30000 / 'init', 1, 0)
> [   76.176767] __send_signal(15, ffff88fff123feb0, ffff881ff1190000 / 'systemd-udevd', 1, 0)
> [   76.185070] __send_signal(15, ffff88fff123feb0, ffff881ff11310f0 / 'systemd-udevd', 1, 0)
> [   76.185772] __send_signal(17, ffff881ff115bdf8, ffff88fff10321e0 / 'systemd-udevd', 1, 0)
> [   76.201536] __send_signal(15, ffff88fff123feb0, ffff881ff12210f0 / 'systemd-udevd', 1, 0)
> [   76.202083] __send_signal(17, ffff881ff11dbdf8, ffff88fff10321e0 / 'systemd-udevd', 1, 0)
> [   76.218146] __send_signal(15, ffff88fff123feb0, ffff881ff12221e0 / 'systemd-udevd', 1, 0)
> [   76.218687] __send_signal(17, ffff881ff1251df8, ffff88fff10321e0 / 'systemd-udevd', 1, 0)
> [   76.234757] __send_signal(15, ffff88fff123feb0, ffff881ff12232d0 / 'systemd-udevd', 1, 0)
> [   76.235294] __send_signal(17, ffff881ff128bdf8, ffff88fff10321e0 / 'systemd-udevd', 1, 0)
> [   76.251368] __send_signal(15, ffff88fff123feb0, ffff881ff12243c0 / 'systemd-udevd', 1, 0)
> [   76.251914] __send_signal(17, ffff881ff12bfdf8, ffff88fff10321e0 / 'systemd-udevd', 1, 0)
> [   76.267982] __send_signal(15, ffff88fff123feb0, ffff881ff12254b0 / 'systemd-udevd', 1, 0)
> [   76.268455] __send_signal(17, ffff881ff12e3df8, ffff88fff10321e0 / 'systemd-udevd', 1, 0)
> [   76.284673] __send_signal(15, ffff88fff123feb0, ffff881ff12265a0 / 'systemd-udevd', 1, 0)
> [   76.290645] __send_signal(17, ffff881ff130ddf8, ffff88fff10321e0 / 'systemd-udevd', 1, 0)
> [   76.301282] __send_signal(15, ffff88fff123feb0, ffff881ff1348000 / 'systemd-udevd', 1, 0)
> [   76.307173] __send_signal(17, ffff881ff1321df8, ffff88fff10321e0 / 'systemd-udevd', 1, 0)
> [   76.317817] __send_signal(15, ffff88fff123feb0, ffff881ff13490f0 / 'systemd-udevd', 1, 0)
> [   76.323840] __send_signal(17, ffff881ff1345df8, ffff88fff10321e0 / 'systemd-udevd', 1, 0)
> [   76.334511] __send_signal(15, ffff88fff123feb0, ffff881ff134a1e0 / 'systemd-udevd', 1, 0)
> [   76.340489] __send_signal(17, ffff881ff1373df8, ffff88fff10321e0 / 'systemd-udevd', 1, 0)
> [   76.351135] __send_signal(15, ffff88fff123feb0, ffff881ff134b2d0 / 'systemd-udevd', 1, 0)
> [   76.357013] __send_signal(17, ffff881ff13a1df8, ffff88fff10321e0 / 'systemd-udevd', 1, 0)
> [   76.367726] __send_signal(15, ffff88fff123feb0, ffff881ff134c3c0 / 'systemd-udevd', 1, 0)
> [   76.373594] __send_signal(17, ffff881ff13a5df8, ffff88fff10321e0 / 'systemd-udevd', 1, 0)
> [   76.390304] __send_signal(15, ffff88fff123feb0, ffff881ff134d4b0 / 'systemd-udevd', 1, 0)
> [   76.390807] __send_signal(17, ffff881ff13cbdf8, ffff88fff10321e0 / 'systemd-udevd', 1, 0)
> [   76.406788] __send_signal(15, ffff88fff123feb0, ffff881ff134e5a0 / 'systemd-udevd', 1, 0)
> [   76.407315] __send_signal(17, ffff881ff13f1df8, ffff88fff10321e0 / 'systemd-udevd', 1, 0)
> [   76.423415] __send_signal(15, ffff88fff123feb0, ffff881fee820000 / 'systemd-udevd', 1, 0)
> [   76.423881] __send_signal(17, ffff881ff13f5df8, ffff88fff10321e0 / 'systemd-udevd', 1, 0)
> [   76.439999] __send_signal(15, ffff88fff123feb0, ffff881fee8210f0 / 'systemd-udevd', 1, 0)
> [   76.440491] __send_signal(17, ffff881fee81ddf8, ffff88fff10321e0 / 'systemd-udevd', 1, 0)
> [   76.456609] __send_signal(15, ffff88fff123feb0, ffff881fee8221e0 / 'systemd-udevd', 1, 0)
> [   76.457169] __send_signal(17, ffff881fee847df8, ffff88fff10321e0 / 'systemd-udevd', 1, 0)
> [   76.473219] __send_signal(15, ffff88fff123feb0, ffff881fee8232d0 / 'systemd-udevd', 1, 0)
> [   76.473728] __send_signal(17, ffff881fee86ddf8, ffff88fff10321e0 / 'systemd-udevd', 1, 0)
> [   76.489831] __send_signal(15, ffff88fff123feb0, ffff881fee8243c0 / 'systemd-udevd', 1, 0)
> [   76.490314] __send_signal(17, ffff881fee875df8, ffff88fff10321e0 / 'systemd-udevd', 1, 0)
> [   76.506441] __send_signal(15, ffff88fff123feb0, ffff881fee8254b0 / 'systemd-udevd', 1, 0)
> [   76.506934] __send_signal(17, ffff881fee89fdf8, ffff88fff10321e0 / 'systemd-udevd', 1, 0)
> [   76.523074] __send_signal(15, ffff88fff123feb0, ffff881fee8265a0 / 'systemd-udevd', 1, 0)
> [   76.523578] __send_signal(17, ffff881fee8c5df8, ffff88fff10321e0 / 'systemd-udevd', 1, 0)
> [   76.539751] __send_signal(15, ffff88fff123feb0, ffff881fee8f8000 / 'systemd-udevd', 1, 0)
> [   76.540991] __send_signal(17, ffff881fee8f3df8, ffff88fff10321e0 / 'systemd-udevd', 1, 0)
> [   76.556278] __send_signal(15, ffff88fff123feb0, ffff881fee8f90f0 / 'systemd-udevd', 1, 0)
> [   76.556853] __send_signal(17, ffff881fee8f7df8, ffff88fff10321e0 / 'systemd-udevd', 1, 0)
> [   76.573009] __send_signal(15, ffff88fff123feb0, ffff881fee8fa1e0 / 'systemd-udevd', 1, 0)
> [   76.568217] __send_signal(17, ffff881fee927df8, ffff88fff10321e0 / 'systemd-udevd', 1, 0)
> [   76.589581] __send_signal(15, ffff88fff123feb0, ffff881fee8fb2d0 / 'systemd-udevd', 1, 0)
> [   76.557071] __send_signal(17, ffff881fee949df8, ffff88fff10321e0 / 'systemd-udevd', 1, 0)
> [   76.606183] __send_signal(15, ffff88fff123feb0, ffff881fee8fc3c0 / 'systemd-udevd', 1, 0)
> [   76.607417] __send_signal(17, ffff881fee96fdf8, ffff88fff10321e0 / 'systemd-udevd', 1, 0)
> [   76.622800] __send_signal(15, ffff88fff123feb0, ffff881fee8fd4b0 / 'systemd-udevd', 1, 0)
> [   76.590235] __send_signal(17, ffff881fee977df8, ffff88fff10321e0 / 'systemd-udevd', 1, 0)
> [   76.639433] __send_signal(15, ffff88fff123feb0, ffff881fee8fe5a0 / 'systemd-udevd', 1, 0)
> [   76.606763] __send_signal(17, ffff881fee9a3df8, ffff88fff10321e0 / 'systemd-udevd', 1, 0)
> [   76.656038] __send_signal(15, ffff88fff123feb0, ffff881fee9f0000 / 'systemd-udevd', 1, 0)
> [   76.657295] __send_signal(17, ffff881fee9cddf8, ffff88fff10321e0 / 'systemd-udevd', 1, 0)
> [   76.672572] __send_signal(15, ffff88fff123feb0, ffff881fee9f10f0 / 'systemd-udevd', 1, 0)
> [   76.673118] __send_signal(17, ffff881fee9f9df8, ffff88fff10321e0 / 'systemd-udevd', 1, 0)
> [   76.689345] __send_signal(15, ffff88fff123feb0, ffff881fee9f21e0 / 'systemd-udevd', 1, 0)
> [   76.685195] __send_signal(17, ffff881fee9fddf8, ffff88fff10321e0 / 'systemd-udevd', 1, 0)
> [   76.705902] __send_signal(15, ffff88fff123feb0, ffff881fee9f32d0 / 'systemd-udevd', 1, 0)
> [   76.707076] __send_signal(17, ffff881feea2ddf8, ffff88fff10321e0 / 'systemd-udevd', 1, 0)
> [   76.722424] __send_signal(15, ffff88fff123feb0, ffff881fee9f43c0 / 'systemd-udevd', 1, 0)
> [   76.723044] __send_signal(17, ffff881feea51df8, ffff88fff10321e0 / 'systemd-udevd', 1, 0)
> [   76.739107] __send_signal(15, ffff88fff123feb0, ffff881fee9f54b0 / 'systemd-udevd', 1, 0)
> [   76.735020] __send_signal(17, ffff881feea75df8, ffff88fff10321e0 / 'systemd-udevd', 1, 0)
> [   76.755749] __send_signal(15, ffff88fff123feb0, ffff881fee9f65a0 / 'systemd-udevd', 1, 0)
> [   76.756929] __send_signal(17, ffff881feea7ddf8, ffff88fff10321e0 / 'systemd-udevd', 1, 0)
> [   76.772261] __send_signal(15, ffff88fff123feb0, ffff881feead8000 / 'systemd-udevd', 1, 0)
> [   76.772815] __send_signal(17, ffff881feeaafdf8, ffff88fff10321e0 / 'systemd-udevd', 1, 0)
> [   76.757287] __send_signal(17, ffff881feead7df8, ffff88fff10321e0 / 'systemd-udevd', 1, 0)
> [   76.765742] __send_signal(17, ffff881fee08bdf8, ffff88fff10343c0 / 'udev', 1, 0)
> [   76.806229] __send_signal(17, ffff88fff123fdf8, ffff881ff2c30000 / 'init', 1, 0)
> [   76.851892] __send_signal(17, ffff883ff19e3df8, ffff88fff10343c0 / 'udev', 1, 0)
> [   76.859490] __send_signal(17, ffff885ff276fdf8, ffff88fff10343c0 / 'udev', 1, 0)
> [   76.862938] __send_signal(17, ffff887ff2151df8, ffff88fff10343c0 / 'udev', 1, 0)
> [   76.870567] __send_signal(17, ffff88fff1aefdf8, ffff881ff2c30000 / 'init', 1, 0)
> [   76.892224] __send_signal(17, ffff889ff25ffdf8, ffff881ff2c30000 / 'init', 1, 0)
> [   76.902651] __send_signal(17, ffff88bff191fdf8, ffff881ff2c30000 / 'init', 1, 0)
> [   76.910928] __send_signal(17, ffff88dff2dcddf8, ffff881ff2c30000 / 'init', 1, 0)
> [   76.929763] __send_signal(17, ffff88fff1b6ddf8, ffff881ff2c30000 / 'init', 1, 0)
> [   76.936449] __send_signal(17, ffff88fff1af5df8, ffff881ff2c30000 / 'init', 1, 0)
> [   76.945662] Kernel panic - not syncing: Attempted to kill init! exitcode=0x00000200
> [   76.945662] 
> [   76.954779] CPU: 2 PID: 1 Comm: init Not tainted 3.14.0-rc4+ #300
> [   76.960962] Hardware name: FUJITSU-SV PRIMEQUEST 1800E2/SB, BIOS PRIMEQUEST 1000 Series BIOS Version 1.24 09/14/2011
> [   76.971653]  ffff883ff1898000 ffff881ff2c2be28 ffffffff816ca8c5 ffff881ff2c30000
> [   76.979163]  ffffffff819b86a0 ffff881ff2c2bea8 ffffffff816c5c19 ffffffff816d4800
> [   76.986674]  ffff881f00000010 ffff881ff2c2beb8 ffff881ff2c2be58 ffff881ff2c2be78
> [   76.994184] Call Trace:
> [   76.996665]  [<ffffffff816ca8c5>] dump_stack+0x4e/0x68
> [   77.001879]  [<ffffffff816c5c19>] panic+0xd2/0x1f9
> [   77.006738]  [<ffffffff816d4800>] ? _raw_write_unlock_irq+0x30/0x60
> [   77.013099]  [<ffffffff810558f7>] do_exit+0x917/0xa20
> [   77.018224]  [<ffffffff81182e0d>] ? __sb_end_write+0x7d/0x90
> [   77.023963]  [<ffffffff816d4ed8>] ? retint_swapgs+0x13/0x1b
> [   77.029617]  [<ffffffff81055a9f>] do_group_exit+0x4f/0xc0
> [   77.035097]  [<ffffffff81055b27>] SyS_exit_group+0x17/0x20
> [   77.040663]  [<ffffffff816d59e9>] system_call_fastpath+0x16/0x1b
> [   77.050447] Kernel Offset: 0x0 from 0xffffffff81000000 (relocation range: 0xffffffff80000000-0xffffffff9fffffff)

Re: post 3.14 serial regression

[Dave Hansen]

On 04/08/2014 02:03 PM, Dave Hansen wrote:
> On 04/08/2014 04:27 AM, One Thousand Gnomes wrote:
>>> At the end, you can see that init is somehow dying.  If I revert this
>>> patch, init is happy again and doesn't die, and the serial console works
>>> like before.
>>
>> Can you check if init is getting a SIGHUP - possibly its opening the
>> device and when it goes away gets a hangup which it isn't catching ?
> 
> I do see plenty of SIGCHLDs and a heap of SIGTERMs to 'systemd-udevd',
> but no SIGHUP.  I do see a "Warning: unable to open an initial console."
> now, though.  (details far below)
> 
> I instrumented uart_remove_one_port().  It *looks* like while searching
> for a uart_port for 0x1008 (my actual port),
> serial8250_find_match_or_unused() finds 0x3e8 since 0x3e8 is
> PORT_UNKNOWN.  The new code unregisters the 0x1008 console since it
> _thinks_ it is about to re-register it.

<sigh>

Looks like this just changed the detection order so my device went from
ttyS2 to ttyS4:

# cat /proc/tty/driver/serial
serinfo:1.0 driver revision:
0: uart:16550A port:000003F8 irq:4 tx:0 rx:0 CTS|DSR|CD
1: uart:16550A port:000002F8 irq:3 tx:0 rx:0
2: uart:unknown port:000003E8 irq:4
3: uart:unknown port:000002E8 irq:3
4: uart:ST16650V2 port:00001008 irq:18 tx:0 rx:0
5: uart:ST16650V2 port:00001000 irq:19 tx:0 rx:0

Re: post 3.14 serial regression

[Greg Kroah-Hartman]

On Tue, Apr 08, 2014 at 02:38:31PM -0700, Dave Hansen wrote:
> On 04/08/2014 02:03 PM, Dave Hansen wrote:
> > On 04/08/2014 04:27 AM, One Thousand Gnomes wrote:
> >>> At the end, you can see that init is somehow dying.  If I revert this
> >>> patch, init is happy again and doesn't die, and the serial console works
> >>> like before.
> >>
> >> Can you check if init is getting a SIGHUP - possibly its opening the
> >> device and when it goes away gets a hangup which it isn't catching ?
> > 
> > I do see plenty of SIGCHLDs and a heap of SIGTERMs to 'systemd-udevd',
> > but no SIGHUP.  I do see a "Warning: unable to open an initial console."
> > now, though.  (details far below)
> > 
> > I instrumented uart_remove_one_port().  It *looks* like while searching
> > for a uart_port for 0x1008 (my actual port),
> > serial8250_find_match_or_unused() finds 0x3e8 since 0x3e8 is
> > PORT_UNKNOWN.  The new code unregisters the 0x1008 console since it
> > _thinks_ it is about to re-register it.
> 
> <sigh>
> 
> Looks like this just changed the detection order so my device went from
> ttyS2 to ttyS4:
> 
> # cat /proc/tty/driver/serial
> serinfo:1.0 driver revision:
> 0: uart:16550A port:000003F8 irq:4 tx:0 rx:0 CTS|DSR|CD
> 1: uart:16550A port:000002F8 irq:3 tx:0 rx:0
> 2: uart:unknown port:000003E8 irq:4
> 3: uart:unknown port:000002E8 irq:3
> 4: uart:ST16650V2 port:00001008 irq:18 tx:0 rx:0
> 5: uart:ST16650V2 port:00001000 irq:19 tx:0 rx:0

That's not good.

Geert, any idea how to fix this?  Or should I just revert your change to
get back to the "working" behavior?

thanks,

greg k-h

Re: post 3.14 serial regression

[Dave Hansen]

On 04/08/2014 05:36 PM, Greg Kroah-Hartman wrote:
>> > Looks like this just changed the detection order so my device went from
>> > ttyS2 to ttyS4:
>> > 
>> > # cat /proc/tty/driver/serial
>> > serinfo:1.0 driver revision:
>> > 0: uart:16550A port:000003F8 irq:4 tx:0 rx:0 CTS|DSR|CD
>> > 1: uart:16550A port:000002F8 irq:3 tx:0 rx:0
>> > 2: uart:unknown port:000003E8 irq:4
>> > 3: uart:unknown port:000002E8 irq:3
>> > 4: uart:ST16650V2 port:00001008 irq:18 tx:0 rx:0
>> > 5: uart:ST16650V2 port:00001000 irq:19 tx:0 rx:0
> That's not good.
> 
> Geert, any idea how to fix this?  Or should I just revert your change to
> get back to the "working" behavior?

During some large bisects on previous kernels, I've noticed it make a
switch from ttyS2->ttyS4 before.  In other words, this might have
restored some *old* behavior inadvertently.

The annoying thing is that these assignments *do* keep swapping around.
 I don't really care whether or not we revert this, only that we pick
one order and stick with it.

Re: post 3.14 serial regression

[Geert Uytterhoeven]

Hi Greg,

On Wed, Apr 9, 2014 at 2:36 AM, Greg Kroah-Hartman
<gregkh@linuxfoundation.org> wrote:
> On Tue, Apr 08, 2014 at 02:38:31PM -0700, Dave Hansen wrote:
>> On 04/08/2014 02:03 PM, Dave Hansen wrote:
>> > On 04/08/2014 04:27 AM, One Thousand Gnomes wrote:
>> >>> At the end, you can see that init is somehow dying.  If I revert this
>> >>> patch, init is happy again and doesn't die, and the serial console works
>> >>> like before.
>> >>
>> >> Can you check if init is getting a SIGHUP - possibly its opening the
>> >> device and when it goes away gets a hangup which it isn't catching ?
>> >
>> > I do see plenty of SIGCHLDs and a heap of SIGTERMs to 'systemd-udevd',
>> > but no SIGHUP.  I do see a "Warning: unable to open an initial console."
>> > now, though.  (details far below)
>> >
>> > I instrumented uart_remove_one_port().  It *looks* like while searching
>> > for a uart_port for 0x1008 (my actual port),
>> > serial8250_find_match_or_unused() finds 0x3e8 since 0x3e8 is
>> > PORT_UNKNOWN.  The new code unregisters the 0x1008 console since it
>> > _thinks_ it is about to re-register it.
>>
>> <sigh>
>>
>> Looks like this just changed the detection order so my device went from
>> ttyS2 to ttyS4:
>>
>> # cat /proc/tty/driver/serial
>> serinfo:1.0 driver revision:
>> 0: uart:16550A port:000003F8 irq:4 tx:0 rx:0 CTS|DSR|CD
>> 1: uart:16550A port:000002F8 irq:3 tx:0 rx:0
>> 2: uart:unknown port:000003E8 irq:4
>> 3: uart:unknown port:000002E8 irq:3
>> 4: uart:ST16650V2 port:00001008 irq:18 tx:0 rx:0
>> 5: uart:ST16650V2 port:00001000 irq:19 tx:0 rx:0
>
> That's not good.
>
> Geert, any idea how to fix this?  Or should I just revert your change to
> get back to the "working" behavior?

Sorry, no idea. Reverting the change will bring back the crash on
unbind for me.

When I read Dave's first email, my first though was "why is
uart_remove_one_port() called on an active port?". But this doesn't
seem to be the case?

Dave: If I understand it correctly, you use console=ttyS2, while the kernel
suddenly changed the order of the serial devices, so your port is no
longer ttyS2, but ttyS4. Hence the serial port is not found, and
uart_remove_one_port() is called on it, taking away your /dev/console for
userspace?

Why does the serial port driver call uart_add_one_port() for ports that
don't exist?
Or if it does exist ("inaccessible and buried inside the system somewhere"),
how is it removed again?

>From the backtrace, it's the call below to uart_remove_one_port()
that removes the port?

/**
 *      serial8250_register_8250_port - register a serial port
 *      @up: serial port template
 *
 *      Configure the serial port specified by the request. If the
 *      port exists and is in use, it is hung up and unregistered
 *      first.
 *
 *      The port is then probed and if necessary the IRQ is autodetected
 *      If this fails an error is returned.
 *
 *      On success the port is ready to use and the line number is returned.
 */
int serial8250_register_8250_port(struct uart_8250_port *up)
{
        ...

        if (uart && uart->port.type != PORT_8250_CIR) {
                if (uart->port.dev)
                        uart_remove_one_port(&serial8250_reg, &uart->port);

where was it added before?

I'm a bit confused...

Gr{oetje,eeting}s,

                        Geert

--
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org

In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
                                -- Linus Torvalds

Re: post 3.14 serial regression

[Dave Hansen]

On 04/09/2014 12:41 PM, Geert Uytterhoeven wrote:
> Dave: If I understand it correctly, you use console=ttyS2, while the kernel
> suddenly changed the order of the serial devices, so your port is no
> longer ttyS2, but ttyS4. Hence the serial port is not found, and
> uart_remove_one_port() is called on it, taking away your /dev/console for
> userspace?

Right.

> Why does the serial port driver call uart_add_one_port() for ports that
> don't exist?
> Or if it does exist ("inaccessible and buried inside the system somewhere"),
> how is it removed again?

The ones buried inside the system are immaterial here.  I just wanted to
explain why I was using a separate PCI card instead of the other serial
ports.

>>From the backtrace, it's the call below to uart_remove_one_port()
> that removes the port?
> 
> /**
>  *      serial8250_register_8250_port - register a serial port
>  *      @up: serial port template
>  *
>  *      Configure the serial port specified by the request. If the
>  *      port exists and is in use, it is hung up and unregistered
>  *      first.
>  *
>  *      The port is then probed and if necessary the IRQ is autodetected
>  *      If this fails an error is returned.
>  *
>  *      On success the port is ready to use and the line number is returned.
>  */
> int serial8250_register_8250_port(struct uart_8250_port *up)
> {
>         ...
> 
>         if (uart && uart->port.type != PORT_8250_CIR) {
>                 if (uart->port.dev)
>                         uart_remove_one_port(&serial8250_reg, &uart->port);
> 
> where was it added before?

Remember, serial8250_find_match_or_unused() will also reuse *EXISTING*
uart_ports if the port is of 'unknown' type.

I believe that port got added during the addition of the
serial8250_isa_devs, and now we're trying to reuse it since it is an
unknown port type.

Re: post 3.14 serial regression

[Geert Uytterhoeven]

Hi Dave,

On Wed, Apr 9, 2014 at 10:04 PM, Dave Hansen <dave@sr71.net> wrote:
> On 04/09/2014 12:41 PM, Geert Uytterhoeven wrote:
>> Dave: If I understand it correctly, you use console=ttyS2, while the kernel
>> suddenly changed the order of the serial devices, so your port is no
>> longer ttyS2, but ttyS4. Hence the serial port is not found, and
>> uart_remove_one_port() is called on it, taking away your /dev/console for
>> userspace?
>
> Right.

Does it work with console=ttyS4?

>>>From the backtrace, it's the call below to uart_remove_one_port()
>> that removes the port?
>>
>> /**
>>  *      serial8250_register_8250_port - register a serial port
>>  *      @up: serial port template
>>  *
>>  *      Configure the serial port specified by the request. If the
>>  *      port exists and is in use, it is hung up and unregistered
>>  *      first.
>>  *
>>  *      The port is then probed and if necessary the IRQ is autodetected
>>  *      If this fails an error is returned.
>>  *
>>  *      On success the port is ready to use and the line number is returned.
>>  */
>> int serial8250_register_8250_port(struct uart_8250_port *up)
>> {
>>         ...
>>
>>         if (uart && uart->port.type != PORT_8250_CIR) {
>>                 if (uart->port.dev)
>>                         uart_remove_one_port(&serial8250_reg, &uart->port);
>>
>> where was it added before?
>
> Remember, serial8250_find_match_or_unused() will also reuse *EXISTING*
> uart_ports if the port is of 'unknown' type.
>
> I believe that port got added during the addition of the
> serial8250_isa_devs, and now we're trying to reuse it since it is an
> unknown port type.

So it gets added, removed, and added again.

I also noticed that unbinding and rebinding the driver doesn't re-attach it
as a serial console.

Gr{oetje,eeting}s,

                        Geert

--
Geert Uytterhoeven -- There's lots of Linux beyond ia32 -- geert@linux-m68k.org

In personal conversations with technical people, I call myself a hacker. But
when I'm talking to journalists I just say "programmer" or something like that.
                                -- Linus Torvalds

Re: post 3.14 serial regression

[Dave Hansen]

On 04/09/2014 01:59 PM, Geert Uytterhoeven wrote:
> On Wed, Apr 9, 2014 at 10:04 PM, Dave Hansen <dave@sr71.net> wrote:
>> On 04/09/2014 12:41 PM, Geert Uytterhoeven wrote:
>>> Dave: If I understand it correctly, you use console=ttyS2, while the kernel
>>> suddenly changed the order of the serial devices, so your port is no
>>> longer ttyS2, but ttyS4. Hence the serial port is not found, and
>>> uart_remove_one_port() is called on it, taking away your /dev/console for
>>> userspace?
>>
>> Right.
> 
> Does it work with console=ttyS4?

Yes, after raising SERIAL_8250_NR_UARTS to >=6.  It had been set to 4
(the Kconfig default).

Re: post 3.14 serial regression

[One Thousand Gnomes]

> I also noticed that unbinding and rebinding the driver doesn't re-attach it
> as a serial console.

Correct. The serial "console" is not hot pluggable.

http://blog.gmane.org/gmane.linux.serial/month=20090301/page=5

related 2009 discussion ..

Alan