Subject: Re: sky2 panic in 2.6.32.1 under load (tty NULL write)

From: Michael Breuer <[email-masked]>
Date: Fri, 01 Jan 2010 15:34:17 -0500

In single user mode:

Looks like the first attempt to run mingetty on tty1 triggers a vhangup 
of more than tty1. Also, the initial console (shell, etc) were open on 
tty1 when I started mingetty on tty1. Looks like the subsequent vhangup 
is what broke things. Also, the vhangup issued from mingetty seems to 
have resulted in tty2 activity as well, although I don't see why it 
should have.

Scenario:

Started in single user mode.
did initctl start tty2 and then switched to tty2 and logged in:
Jan  1 15:11:42 mail kernel: opening tty2...
Jan  1 15:11:42 mail kernel: tty2 vhangup...
Jan  1 15:11:42 mail kernel: tty_release_dev of tty2 (tty count=1)...
Jan  1 15:11:42 mail kernel: freeing tty structure...
Jan  1 15:11:42 mail kernel: opening tty2...
Jan  1 15:11:42 mail kernel: tty2 vhangup...
Jan  1 15:11:42 mail kernel: opening tty2...
Jan  1 15:11:42 mail kernel: tty_release_dev of tty2 (tty count=2)...
Jan  1 15:11:42 mail kernel: opening tty2...
Jan  1 15:11:42 mail kernel: tty_release_dev of tty2 (tty count=2)...
Jan  1 15:11:42 mail kernel: opening tty2...
Jan  1 15:11:42 mail kernel: tty_release_dev of tty2 (tty count=2)...

Then (and note that time should have advanced, but didn't): initctl 
start tty1 (previously, the initial shell from single user mode was up):

Jan  1 15:11:42 mail kernel: opening tty1...
Jan  1 15:11:42 mail kernel: tty1 vhangup...
Jan  1 15:11:42 mail kernel: tty_release_dev of tty1 (tty count=3)...
Jan  1 15:11:42 mail kernel: opening tty1...
Jan  1 15:11:42 mail kernel: opening tty2...
Jan  1 15:11:42 mail kernel: tty_release_dev of tty2 (tty count=2)...
Jan  1 15:11:42 mail kernel: tty_release_dev of tty1 (tty count=3)...
Jan  1 15:11:42 mail kernel: tty1 vhangup...
Jan  1 15:11:42 mail kernel: error attempted to write to tty [0x(null)] 
= NULL
Jan  1 15:11:42 mail kernel: opening tty2...
Jan  1 15:11:42 mail kernel: tty_release_dev of tty2 (tty count=2)...
Jan  1 15:11:42 mail kernel: opening tty2...
Jan  1 15:11:42 mail kernel: opening tty2...
Jan  1 15:11:42 mail kernel: tty_release_dev of tty2 (tty count=3)...
Jan  1 15:11:42 mail kernel: opening tty2...
Jan  1 15:11:42 mail kernel: tty_release_dev of tty2 (tty count=3)...
Jan  1 15:11:42 mail kernel: opening tty2...
Jan  1 15:11:42 mail kernel: tty_release_dev of tty2 (tty count=3)...
Jan  1 15:11:42 mail kernel: opening tty2...
Jan  1 15:11:42 mail kernel: tty_release_dev of tty2 (tty count=3)...
Jan  1 15:11:42 mail kernel: opening tty2...
Jan  1 15:11:42 mail kernel: tty_release_dev of tty2 (tty count=3)...
Jan  1 15:11:42 mail kernel: opening tty2...
Jan  1 15:11:42 mail kernel: tty_release_dev of tty2 (tty count=3)...
Jan  1 15:11:42 mail kernel: opening tty2...
Jan  1 15:11:42 mail kernel: tty_release_dev of tty2 (tty count=3)...
Jan  1 15:11:42 mail kernel: opening tty2...
Jan  1 15:11:42 mail kernel: opening tty2...
Jan  1 15:11:42 mail kernel: tty_release_dev of tty2 (tty count=4)...

While I was doing this, I was watching dmesg, not /var/log/message. 
Didn't notice time was stuck...
Then, I did telinit 5:
Jan  1 15:11:42 mail kernel: sky2 eth1: enabling interface
Jan  1 15:11:42 mail kernel: ADDRCONF(NETDEV_UP): eth1: link is not ready
Jan  1 15:11:42 mail kernel: sky2 eth1: Link is up at 100 Mbps, full 
duplex, flow control rx
Jan  1 15:11:42 mail kernel: ADDRCONF(NETDEV_CHANGE): eth1: link becomes 
ready
Jan  1 15:11:42 mail kernel: opening tty2...
Jan  1 15:11:42 mail kernel: tty_release_dev of tty2 (tty count=4)...
Jan  1 15:11:42 mail kernel: opening tty1...
Jan  1 15:11:42 mail kernel: tty_release_dev of tty1 (tty count=2)...
Jan  1 15:11:42 mail kernel: opening tty1...
Jan  1 15:11:42 mail kernel: tty_release_dev of tty1 (tty count=2)...
Jan  1 15:11:42 mail kernel: opening tty1...
Jan  1 15:11:42 mail kernel: tty_release_dev of tty1 (tty count=2)...
Jan  1 15:11:42 mail kernel: opening tty1...
Jan  1 15:11:42 mail kernel: tty_release_dev of tty1 (tty count=2)...
Jan  1 15:11:42 mail kernel: opening tty1...
Jan  1 15:11:42 mail kernel: tty_release_dev of tty1 (tty count=2)...
Jan  1 15:11:42 mail kernel: opening tty1...
Jan  1 15:11:42 mail kernel: tty_release_dev of tty1 (tty count=2)...
Jan  1 15:11:42 mail kernel: opening tty1...
Jan  1 15:11:42 mail kernel: tty_release_dev of tty1 (tty count=2)...
Jan  1 15:11:42 mail kernel: opening tty1...
Jan  1 15:11:42 mail kernel: tty_release_dev of tty1 (tty count=2)...
Jan  1 15:11:42 mail kernel: IPv6 over IPv4 tunneling driver
Jan  1 15:11:42 mail kernel: sit0: Disabled Privacy Extensions
Jan  1 15:11:42 mail kernel: opening tty1...
Jan  1 15:11:42 mail kernel: tty_release_dev of tty1 (tty count=2)...
Jan  1 15:11:42 mail kernel: SELinux: initialized (dev cgroup, type 
cgroup), uses genfs_contexts
Jan  1 15:11:42 mail kernel: opening tty1...
Jan  1 15:11:42 mail kernel: tty_release_dev of tty1 (tty count=2)...
Jan  1 15:11:42 mail kernel: opening tty1...
Jan  1 15:11:42 mail kernel: tty_release_dev of tty1 (tty count=2)...
Jan  1 15:11:42 mail kernel: audit rule for LSM 'dhclient_t' is invalid
Jan  1 15:11:42 mail kernel: audit rule for LSM 'mcstransd_t' is invalid
Jan  1 15:11:42 mail kernel: audit rule for LSM 'samba_t' is invalid
Jan  1 15:11:42 mail kernel: audit rule for LSM 'dhclient_t' is invalid
Jan  1 15:11:42 mail kernel: audit rule for LSM 'mcstransd_t' is invalid
Jan  1 15:11:42 mail kernel: audit rule for LSM 'samba_t' is invalid
Jan  1 15:11:42 mail kernel: opening tty1...
Jan  1 15:11:42 mail kernel: tty_release_dev of tty1 (tty count=2)...
Jan  1 15:11:42 mail kernel: opening tty1...
Jan  1 15:11:42 mail kernel: tty_release_dev of tty1 (tty count=2)...
Jan  1 15:11:42 mail kernel: opening tty1...
Jan  1 15:11:42 mail kernel: tty_release_dev of tty1 (tty count=2)...
Jan  1 15:11:42 mail kernel: opening tty1...
Jan  1 15:11:42 mail kernel: tty_release_dev of tty1 (tty count=2)...
Jan  1 15:11:42 mail kernel: opening tty2...
Jan  1 15:11:42 mail kernel: tty_release_dev of tty2 (tty count=4)...
Jan  1 15:11:42 mail kernel: opening tty1...
Jan  1 15:11:42 mail cpuspeed: Enabling ondemand cpu frequency scaling 
governor
Jan  1 15:11:42 mail kernel: tty_release_dev of tty1 (tty count=2)...
Jan  1 15:11:42 mail kernel: opening tty1...
Jan  1 15:11:42 mail kernel: tty_release_dev of tty1 (tty count=2)...
Jan  1 15:11:42 mail kernel: opening tty1...
Jan  1 15:11:42 mail kernel: tty_release_dev of tty1 (tty count=2)...
Jan  1 15:11:42 mail kernel: opening tty1...
Jan  1 15:11:42 mail kernel: tty_release_dev of tty1 (tty count=2)...
Jan  1 15:11:42 mail kernel: opening tty1...
Jan  1 15:11:42 mail kernel: tty_release_dev of tty1 (tty count=2)...
Jan  1 15:11:42 mail kernel: opening tty1...
Jan  1 15:11:42 mail kernel: tty_release_dev of tty1 (tty count=2)...
Jan  1 15:11:42 mail kernel: opening tty1...
Jan  1 15:11:42 mail kernel: tty_release_dev of tty1 (tty count=2)...
Jan  1 15:11:42 mail kernel: opening tty1...
Jan  1 15:11:42 mail kdump: kexec: loaded kdump kernel
Jan  1 15:11:42 mail kdump: started up
Jan  1 15:11:42 mail kernel: tty_release_dev of tty1 (tty count=2)...
Jan  1 15:11:42 mail kernel: opening tty1...
Jan  1 15:11:43 mail kernel: tty_release_dev of tty1 (tty count=2)...

This is when time increments again ... time jumped ahead and was OK by 
the time ntp started. Looks like system time was OK, but syslog was 
backlogged.

On 01/01/2010 02:26 PM, Michael Breuer wrote:
> Running with TTY_DEBUG_HANGUP:
>
> On boot - lots of stuff opening and closing tty1. Once up and stable 
> (runlevel 3), I did initctl stop tty1, and then initctl start tty1. 
> This is what was logged:
>
> Jan  1 14:03:21 mail root: close mingetty1
> Jan  1 14:03:21 mail kernel: tty_release_dev of tty1 (tty count=6)...
> Jan  1 14:03:21 mail kernel: tty_release_dev of tty1 (tty count=5)...
> Jan  1 14:03:21 mail kernel: tty1 vhangup...
> Jan  1 14:03:21 mail init: tty1 main process (6031) killed by TERM signal
> Jan  1 14:03:36 mail root: start mingetty1
> Jan  1 14:03:36 mail kernel: error attempted to write to tty 
> [0x(null)] = NULL
> Jan  1 14:03:36 mail kernel: opening tty1...
> Jan  1 14:03:36 mail kernel: tty1 vhangup...
> Jan  1 14:03:36 mail kernel: tty_release_dev of tty1 (tty count=5)...
>
> Start/stop of mingetty on other ttys does not get the NULL write 
> error. I am always getting the NULL error when starting mingetty on tty1.
>
> For example:
> Jan  1 14:04:11 mail root: restart mingetty2
> Jan  1 14:04:11 mail init: tty2 main process (6029) killed by TERM signal
> Jan  1 14:04:11 mail kernel: tty_release_dev of tty7 (tty count=2)...
> Jan  1 14:04:11 mail kernel: tty_release_dev of tty2 (tty count=1)...
> Jan  1 14:04:11 mail kernel: freeing tty structure...
> Jan  1 14:04:11 mail kernel: opening tty2...
> Jan  1 14:04:11 mail kernel: tty2 vhangup...
> Jan  1 14:04:11 mail kernel: tty_release_dev of tty2 (tty count=1)...
> Jan  1 14:04:11 mail kernel: freeing tty structure...
>
> While starting/stopping tty2 and X was coming up, I also got this:
>
> Jan  1 14:04:11 mail root: restart mingetty2
> Jan  1 14:04:11 mail init: tty2 main process (6029) killed by TERM signal
> Jan  1 14:04:11 mail kernel: tty_release_dev of tty7 (tty count=2)...
> Jan  1 14:04:11 mail kernel: tty_release_dev of tty2 (tty count=1)...
> Jan  1 14:04:11 mail kernel: freeing tty structure...
> Jan  1 14:04:11 mail kernel: opening tty2...
> Jan  1 14:04:11 mail kernel: tty2 vhangup...
> Jan  1 14:04:11 mail kernel: tty_release_dev of tty2 (tty count=1)...
> Jan  1 14:04:11 mail kernel: freeing tty structure...
> Jan  1 14:04:17 mail gnome-session[6832]: WARNING: Could not parse 
> desktop file 
> /home/mbreuer/.config/autostart/xfce4-tips-autostart.desktop: Key file 
> does not have key 'Name'
> Jan  1 14:04:17 mail gnome-session[6832]: WARNING: could not read 
> /home/mbreuer/.config/autostart/xfce4-tips-autostart.desktop
> Jan  1 14:04:19 mail pulseaudio[7002]: pid.c: Stale PID file, 
> overwriting.
> Jan  1 14:04:20 mail kernel: opening tty2...
> Jan  1 14:04:20 mail kernel: opening pts2...
> Jan  1 14:04:20 mail kernel: opening pts2...
> Jan  1 14:04:20 mail kernel: tty_release_dev of pts2 (tty count=3)...
> Jan  1 14:04:20 mail kernel: opening pts2...
> Jan  1 14:04:20 mail kernel: tty_release_dev of pts2 (tty count=3)...
> Jan  1 14:04:20 mail kernel: opening pts3...
> Jan  1 14:04:20 mail kernel: opening pts3...
> Jan  1 14:04:20 mail kernel: tty_release_dev of pts3 (tty count=3)...
> Jan  1 14:04:20 mail kernel: opening pts3...
> Jan  1 14:04:20 mail kernel: tty_release_dev of pts3 (tty count=3)...
> Jan  1 14:04:20 mail kernel: opening pts4...
> Jan  1 14:04:20 mail kernel: opening pts4...
> Jan  1 14:04:20 mail kernel: tty_release_dev of pts4 (tty count=3)...
> Jan  1 14:04:20 mail kernel: opening pts4...
> Jan  1 14:04:21 mail kernel: tty_release_dev of pts4 (tty count=3)...
> Jan  1 14:04:21 mail kernel: DMA-API: debugging out of memory - disabling
> Jan  1 14:04:23 mail pulseaudio[7417]: pid.c: Daemon already running.
> Jan  1 14:04:24 mail kernel: sky2 0000:06:00.0: error interrupt 
> status=0x8
> Jan  1 14:04:24 mail kernel: sky2 Tx ring pending=45...52 report=45 
> done=47
> Jan  1 14:04:24 mail kernel: 44: 0x0: 0xf26a40be(9014)
> Jan  1 14:04:24 mail kernel: 46: 0x0: 0xf26a00be(9014)
> Jan  1 14:04:24 mail kernel: 48: 0x0: 0xf269c0be(9014)
> Jan  1 14:04:24 mail kernel: 50: 0x0: 0xf26980be(9014)
> Jan  1 14:04:24 mail kernel: sky2 0000:06:00.0: error interrupt 
> status=0x8
> Jan  1 14:04:24 mail kernel: sky2 Tx ring pending=47...52 report=47 
> done=49
> Jan  1 14:04:24 mail kernel: 46: 0x0: 0xf26a00be(9014)
> Jan  1 14:04:24 mail kernel: 48: 0x0: 0xf269c0be(9014)
> Jan  1 14:04:24 mail kernel: 50: 0x0: 0xf26980be(9014)
>
> Note the sky2 errors (this time not under load).
>
> It looks like there is something bad going on with the tty driver.
>
>
> On 01/01/2010 12:42 PM, Michael Breuer wrote:
>> More results... Seems that this is related to the tty (or maybe vt or 
>> maybe console) driver. I had disabled mingetty on tty1 as a 
>> workaround to a Fedora/KDE issue. When I reenabled it, I was then 
>> able to recreate this problem (sky2) in runlevel 3.
>>
>> Retesting, it seems that the following conditions must be met in 
>> order for the interrupt errors to happen:
>>
>> 1) mingetty running on tty1 before the start of the test run
>> 2) High sustained incoming load - 25MB/sec or more (as reported by 
>> nethogs)
>> 3) I've only been able to recreate this using samba & a Windows 7 
>> backup - but there could be other triggers
>>
>> As it happens, much of my other data all came down to mingetty 
>> starting or not starting on tty1 at specific points of test 
>> preparation. At this point I can recreate 100% of the time if I 
>> ensure that there is a mingetty running on tty1, regardless of 
>> runlevel; and I can not recreate 100% of the time when there is no 
>> mingetty running on tty1 at the start of the test. The results do not 
>> change if I start or stop mingetty on tty1 during the test. It's 
>> possible that X running on tty1 may also trigger the issue, but I 
>> haven't tested that. Note that running mingetty on the other tty's 
>> does not affect the outcome of the test. The test is also unaffected 
>> if I chvt to or away from tty1 before the test. I do not have to be 
>> logged in at the console (on any vt) to trigger the issue.
>>
>> In a nutshell, to recreate: make sure there is a mingetty running on 
>> tty1, blast traffic into the system on eth0 (sky2).
>>
>>
>>
>>
>> On 12/31/2009 1:09 PM, Michael Breuer wrote:
>>> Did some more digging today... Haven't nailed it, but there's 
>>> something going on with X and tty...
>>>
>>> Among other things, when I telinit 3 && telinit 5 the tty keeps 
>>> switching between 7 and 8 (nothing else running on either tty). It 
>>> would appear that somehow the tty deallocation isn't complete when X 
>>> restarts. Also, X grabbing a tty seems to be a requisite step in 
>>> recreating the sky2 issue.
>>>
>>> On 12/30/2009 1:10 PM, Stephen Hemminger wrote:
>>>> On Wed, 30 Dec 2009 10:40:56 -0500
>>>> Michael Breuer<[email-masked]>  wrote:
>>>>
>>>>> Dec 30 10:37:14 mail kernel: sky2 0000:06:00.0: error interrupt
>>>>> status=0x40000008
>>>>> Dec 30 10:37:14 mail kernel: sky2 Tx ring pending=31...40 
>>>>> report=35 done=35
>>>>> Dec 30 10:37:14 mail kernel: 30: 0x0: 0xeb50c0ca(9014)
>>>>> Dec 30 10:37:14 mail kernel: 32: 0x0: 0xeb5080ca(9014)
>>>>> Dec 30 10:37:14 mail kernel: 34: 0x0: 0xeb5040ca(9014)
>>>>> Dec 30 10:37:14 mail kernel: 36: 0x0: 0xeb5000ca(9014)
>>>>> Dec 30 10:37:14 mail kernel: 38: 0x0: 0xeb4fc0ca(9014)
>>>> You must be using 9K MTU.  Do you see the problem with smaller
>>>> MTU?
>>>>
>>>>> Dec 30 10:37:14 mail kernel: sky2 0000:06:00.0: error interrupt
>>>>> status=0x40000008
>>>>> Dec 30 10:37:14 mail kernel: sky2 Tx ring pending=87...92 
>>>>> report=89 done=91
>>>>> Dec 30 10:37:14 mail kernel: 86: 0x0: 0xeafd80ca(9014)
>>>>> Dec 30 10:37:14 mail kernel: 88: 0x0: 0xeafd40ca(9014)
>>>>> Dec 30 10:37:14 mail kernel: 90: 0x0: 0xeafd00ca(9014)
>>>>> Dec 30 10:37:15 mail kernel: sky2 0000:06:00.0: error interrupt 
>>>>> status=0x8
>>>>> Dec 30 10:37:15 mail kernel: sky2 Tx ring pending=39...42 
>>>>> report=39 done=41
>>>>> Dec 30 10:37:15 mail kernel: 38: 0x0: 0xe5fec0ca(9014)
>>>>> Dec 30 10:37:15 mail kernel: 40: 0x0: 0xe5fe80ca(9014)
>>>>> Dec 30 10:37:15 mail kernel: sky2 0000:06:00.0: error interrupt
>>>>> status=0x40000008
>>>>> Dec 30 10:37:15 mail kernel: sky2 Tx ring pending=117...124 
>>>>> report=119
>>>>> done=119
>>>>> Dec 30 10:37:15 mail kernel: 116: 0x0: 0xe5d6c0ca(9014)
>>>>> Dec 30 10:37:15 mail kernel: 118: 0x0: 0xe5d680ca(9014)
>>>>> Dec 30 10:37:15 mail kernel: 120: 0x0: 0xe5d660ca(5938)
>>>>> Dec 30 10:37:15 mail kernel: 122: 0x0: 0xe5d640ca(4213)
>>>
>>
>> -- 
>> To unsubscribe from this list: send the line "unsubscribe 
>> linux-kernel" in
>> the body of a message to [email-masked]
>> More majordomo info at  http://vger.kernel.org/majordomo-info.html
>> Please read the FAQ at  http://www.tux.org/lkml/
>
> -- 
> To unsubscribe from this list: send the line "unsubscribe 
> linux-kernel" in
> the body of a message to [email-masked]
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/