ROSE: Misc fixes

DaveM's recent email regarding a crash triggered by the attempt to send IP over rose prompted me to review the ROSE code again. I found four race conditions and from what Bernard writes in a recent email about wrong rose_neighbour->use counters one of these fixes may actually be a practical problem.

- Patch [1/7] fixes a race that is unlikely to hit in a typical system and even if so the result would be a very small number of packets attempted to be sent to the wrong destination.
- Patch [2/7] is a cleanup preparing for [3/7]
- Patch [3/7] fixes the kernel side of the rose_callsign access race by protecting it with a spinlock.
- Patch [4/7] makes struct rose_neigh member use an atomic_t. This was noticed by code review but hopefully fixes the mismatching use counter recently reported by Bernard Pidoux.
- Patch [5/7] converts rose_neigh_no into an atomic_t. Previously there was a race condition which may have resulted in multiple rose_route structures using the same rose_neigh_no value and rose_neigh_no being incremented by fewer than the number of racing accesses.
- Patch [6/7] and [7/7] fix some coding style issues.

Test reports would be apreciated.

Thanks,

Ralf

Ralf Baechle (7):
NET: ROSE: Fix race in SIOCRSSL2CALL ioctl accessing userspace.
NET: ROSE: Factor our common code from functions.
NET: ROSE: Protect rose_callsign with a spinlock
NET: ROSE: Make neighbour->use atomic
NET: ROSE: Make rose_neigh_no atomic.
NET: ROSE: Move return statements hidden behind an if to their own line
NET: ROSE: Fix formatting.

 include/net/rose.h    |    7 +++++--
 net/rose/af_rose.c    |   30 +++++++++++++++++++++---------
 net/rose/rose_in.c    |   13 +++++++------
 net/rose/rose_link.c  |   38 ++++++++++++++++++++++++--------------
 net/rose/rose_route.c |   32 +++++++++++++++++---------------
 net/rose/rose_subr.c  |    3 ++-
 net/rose/rose_timer.c |    3 ++-
 7 files changed, 78 insertions(+), 48 deletions(-)

1.7.4.4

The SIOCRSSL2CALL ioctl may abort before the complete callsign has been copied from userspace, for example when the part of it is in a PROT_NONE mapping.

To: [email protected]
Cc: Bernard F6BVP <[email protected]>

---
 net/rose/af_rose.c |    5 ++++-
 1 files changed, 4 insertions(+), 1 deletions(-)

index f9ea925..710df37 100644
@@ -1289,6 +1289,8 @@ static int rose_ioctl(struct socket *sock, unsigned int cmd, unsigned long arg)
 	void __user *argp = (void __user *)arg;
 
 	switch (cmd) {
+		ax25_address tmp_call;
+
 	case TIOCOUTQ: {
 		long amount;
 

@@ -1352,8 +1354,9 @@ static int rose_ioctl(struct socket *sock, unsigned int cmd, unsigned long arg)
 		if (!capable(CAP_NET_ADMIN)) return -EPERM;
 		if (ax25cmp(&rose_callsign, &null_ax25_address) != 0)
 			ax25_listen_release(&rose_callsign, NULL);
-		if (copy_from_user(&rose_callsign, argp, sizeof(ax25_address)))
+		if (copy_from_user(&tmp_call, argp, sizeof(ax25_address)))
 			return -EFAULT;
+		memcpy(&rose_callsign, &tmp_call, sizeof(ax25_address));
 		if (ax25cmp(&rose_callsign, &null_ax25_address) != 0)
 			return ax25_listen_register(&rose_callsign, NULL);
 

1.7.4.4

This will simplify a later fix.

To: [email protected]
Cc: Bernard F6BVP <[email protected]>

---
 net/rose/rose_link.c |   32 ++++++++++++++++++--------------
 1 files changed, 18 insertions(+), 14 deletions(-)

index fa5f564..fa8703b 100644
@@ -94,6 +94,15 @@ static void rose_t0timer_expiry(unsigned long param)
 	rose_start_t0timer(neigh);
 }
 
+static void rose_get_neigh_callsign(ax25_address *rose_call,
+	struct rose_neigh *neigh)
+{
+	if (ax25cmp(&rose_callsign, &null_ax25_address) == 0)
+		memcpy(rose_call, neigh->dev->dev_addr, sizeof(rose_call));
+	else
+		memcpy(rose_call, &rose_callsign, sizeof(rose_call));
+}
+
 /*
  *	Interface to ax25_send_frame. Changes my level 2 callsign depending
  *	on whether we have a global ROSE callsign or use the default port

@@ -101,16 +110,14 @@ static void rose_t0timer_expiry(unsigned long param)
  */
 static int rose_send_frame(struct sk_buff *skb, struct rose_neigh *neigh)
 {
-	ax25_address *rose_call;
+	ax25_address rose_call;
 	ax25_cb *ax25s;
 
-	if (ax25cmp(&rose_callsign, &null_ax25_address) == 0)
-		rose_call = (ax25_address *)neigh->dev->dev_addr;
-	else
-		rose_call = &rose_callsign;
-
 	ax25s = neigh->ax25;
-	neigh->ax25 = ax25_send_frame(skb, 260, rose_call, &neigh->callsign, neigh->digipeat, neigh->dev);
+	rose_get_neigh_callsign(&rose_call, neigh);
+	neigh->ax25 = ax25_send_frame(skb, 260, &rose_call,
+				      &neigh->callsign, neigh->digipeat,
+				      neigh->dev);
 	if (ax25s)
 		ax25_cb_put(ax25s);
 

@@ -124,16 +131,13 @@ static int rose_send_frame(struct sk_buff *skb, struct rose_neigh *neigh)
  */
 static int rose_link_up(struct rose_neigh *neigh)
 {
-	ax25_address *rose_call;
+	ax25_address rose_call;
 	ax25_cb *ax25s;
 
-	if (ax25cmp(&rose_callsign, &null_ax25_address) == 0)
-		rose_call = (ax25_address *)neigh->dev->dev_addr;
-	else
-		rose_call = &rose_callsign;
-
 	ax25s = neigh->ax25;
-	neigh->ax25 = ax25_find_cb(rose_call, &neigh->callsign, neigh->digipeat, neigh->dev);
+	rose_get_neigh_callsign(&rose_call, neigh);
+	neigh->ax25 = ax25_find_cb(&rose_call, &neigh->callsign,
+				   neigh->digipeat, neigh->dev);
 	if (ax25s)
 		ax25_cb_put(ax25s);
 

1.7.4.4

On a typical installation rose_callsign is only ever changed once at configuration time probably after bootup so this is a very unlikely race to be hit in real life.

To: [email protected]
Cc: Bernard F6BVP <[email protected]>

---
 include/net/rose.h   |    2 ++
 net/rose/af_rose.c   |    7 ++++++-
 net/rose/rose_link.c |   12 +++++++++---
 3 files changed, 17 insertions(+), 4 deletions(-)

index 555dd19..0474a83 100644
@@ -8,6 +8,7 @@
 #define _ROSE_H 
 
 #include <linux/rose.h>
+#include <linux/spinlock.h>
 #include <net/sock.h>
 
 #define	ROSE_ADDR_LEN			5

@@ -150,6 +151,7 @@ struct rose_sock {
 
 /* af_rose.c */
 extern ax25_address rose_callsign;
+extern spinlock_t rose_callsign_lock;
 extern int  sysctl_rose_restart_request_timeout;
 extern int  sysctl_rose_call_request_timeout;
 extern int  sysctl_rose_reset_request_timeout;

index 710df37..a339ea5 100644
@@ -67,6 +67,7 @@ static DEFINE_SPINLOCK(rose_list_lock);
 static const struct proto_ops rose_proto_ops;
 
 ax25_address rose_callsign;
+DEFINE_SPINLOCK(rose_callsign_lock);
 
 /*
  * ROSE network devices are virtual network devices encapsulating ROSE

@@ -1536,7 +1537,9 @@ static int __init rose_proto_init(void)
 	if (rc != 0)
 		goto out;
 
-	rose_callsign = null_ax25_address;
+	spin_lock(&rose_callsign_lock);
+	memcpy(&rose_callsign, &null_ax25_address, sizeof(rose_callsign));
+	spin_unlock(&rose_callsign_lock);
 
 	dev_rose = kzalloc(rose_ndevs * sizeof(struct net_device *), GFP_KERNEL);
 	if (dev_rose == NULL) {

@@ -1620,8 +1623,10 @@ static void __exit rose_exit(void)
 	ax25_protocol_release(AX25_P_ROSE);
 	ax25_linkfail_release(&rose_linkfail_notifier);
 
+	spin_lock(&rose_callsign_lock);
 	if (ax25cmp(&rose_callsign, &null_ax25_address) != 0)
 		ax25_listen_release(&rose_callsign, NULL);
+	spin_unlock(&rose_callsign_lock);
 
 #ifdef CONFIG_SYSCTL
 	rose_unregister_sysctl();

index fa8703b..9d3322f 100644
@@ -97,10 +97,16 @@ static void rose_t0timer_expiry(unsigned long param)
 static void rose_get_neigh_callsign(ax25_address *rose_call,
 	struct rose_neigh *neigh)
 {
-	if (ax25cmp(&rose_callsign, &null_ax25_address) == 0)
+	spin_lock(&rose_callsign_lock);
+	if (ax25cmp(&rose_callsign, &null_ax25_address) == 0) {
+		spin_unlock(&rose_callsign_lock);
 		memcpy(rose_call, neigh->dev->dev_addr, sizeof(rose_call));
-	else
-		memcpy(rose_call, &rose_callsign, sizeof(rose_call));
+
+		return;
+	}
+
+	memcpy(rose_call, &rose_callsign, sizeof(rose_call));
+	spin_unlock(&rose_callsign_lock);
 }
 
 /*

1.7.4.4

Hi,

mheardd daemon application, as part of ax25tools, collects all heard callsigns on AX.25 devices into a data base together with times and dates of first time and last time heard.

I noticed that in some cases, mheard would read data base and list a number of empty lines with zero packet received. Empty lines displayed roll up the list and sometime makes uncomfortable the reading of captured callsigns.

With this patch mheard client will display only usefull information and skip empty records.

Patch and updated source can be downloaded from ve7fet Lee's "unofficial repository":

https://code.google.com/p/linuxax25/source/list

73 de Bernard, f6bvp

Hello Bernard,

please send us a diff for the official tree.

vy 73,
- Thomas dl9sau

On 2013-08-06 19:57:51 +0200, f6bvp@free <[email protected]> wrote in <[email protected]>:

Hello Thomas,

As you know mheard is a user application included in ax25tools package. It is not part of Linux kernel.

Here is a diff of ax25tools/ax25/mheard.c

73 de Bernard, f6bvp

Index: ax25/mheard.c
===================================================================
@@ -68,7 +68,8 @@
                        call = ax25_ntoa(&pr->entry.from_call);
                        if ((s = strstr(call, "-0")) != NULL)
                                *s = '\0';
-                       printf("%-10s %-5s %5d   %s\n",
+                       if (pr->entry.count != 0)
+                               printf("%-10s %-5s %5d   %s\n",
                                call, pr->entry.portname, 

pr->entry.count, lh);
                        break;
                case 1:
@@ -91,7 +92,8 @@
                        }
                        if (pr->entry.ndigis >= 4)
                                strcat(buffer, ",...");
-                       printf("%-70s %-5s\n",
+                       if (pr->entry.count != 0)
+                               printf("%-70s %-5s\n",
                                buffer, pr->entry.portname);
                        break;
                case 2:
@@ -102,14 +104,16 @@
                        call = ax25_ntoa(&pr->entry.from_call);
                        if ((s = strstr(call, "-0")) != NULL)
                                *s = '\0';
-                       printf("%-10s %-5s %5d %5d %5d  %s  %s\n",
+                       if (pr->entry.count != 0)
+                               printf("%-10s %-5s %5d %5d %5d %s  %s\n",
                                call, pr->entry.portname, 
pr->entry.iframes, pr->entry.sframes, pr->entry.uframes, fh, lh);
                        break;
                case 3:
                        call = ax25_ntoa(&pr->entry.from_call);
                        if ((s = strstr(call, "-0")) != NULL)
                                *s = '\0';
-                       printf("%-10s %-5s %5d %5s ",
+                       if (pr->entry.count != 0) {
+                               printf("%-10s %-5s %5d %5s ",
                                call, pr->entry.portname, 
pr->entry.count, types[pr->entry.type]);
                        if (pr->entry.mode & MHEARD_MODE_ARP)
                                printf(" ARP");
@@ -136,6 +140,7 @@
                        if (pr->entry.mode & MHEARD_MODE_UNKNOWN)
                                printf(" Unknown");
                        printf("\n");
+                       }
                        break;
        }

}

--
To unsubscribe from this list: send the line "unsubscribe linux-hams" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

On 2013-08-06 19:57:51 +0200, f6bvp@free <[email protected]> wrote in <[email protected]>:

The data file is a block list of struct mheard_struct. This data is stored along with "in_use" and "position" (SEEK) in mheard_list_struct for operation in memory. This data is synced to file after each heard AX.25 frame.

findentry() operates on the memory list mheard_list_struct. It
- looks for an exact match (from call + portname)
- If not found, it searches for the first "not in_use" in the memory list mheard_list_struct. It marks it in_use and returns a fictive SEEK (for SEEK_END usage during the later file sync)
- If the list is "full", it searches for the oldest entry, and nulls the data.

This looks fine.

If you look in the mheard program for "count != 0" only for displaying the data, then calls with exactly heard 65536 (sizeof(unsigned int) packets are not display. Ok, this is not large issue. But more reliably is, that a callsign never starts with \0 (calls are stored left aligned, and have only chars like A..Z, 0..9 and ' ').

Let's look at the potential race-conditions that causes the "bad" entries you try to filter out.

I assume, that condition 2 of findentry() is responsible. It looks for the first "hole" (i. E. if you just have heard 1 call, the first hole in the list of 1000 nodes is the second position) and marks it "in_use".

findendry() is called in the large mainloop after each packet receiption.

First race-condition:

                if (!ax25_validate(data + 0) || !ax25_validate(data + AXLEN)) {
                        if (logging)
                                syslog(LOG_WARNING, "invalid callsign on port %s\n", port);
                        continue;
                }

=> After the receiption of a corrupted callsign in the from or to address field, the packet will be ignored.
The field is marked as in_use. The count is 0 (because the complete struct is nulled).

Next race-condition:
From and To call, port name and ndigis is filled.
Afterwards, the size of the packet is looked up. If 0, then it's thrown away:

                if (size == 0) {
                        if (logging)
                                syslog(LOG_WARNING, "packet too short\n");
                        continue;
                }

=> The field is marked in use. The data filled in is incomplete (other info would have stored later, like packet type, heard time, ..). count is still 0.

After this: mheard->entry.count++;

After the next new call has been heard after this race-condx, fseek() makes a gap between the last entry and this new entry, that contains zero data.

==> mheardd may cause empty blocks. and mheard does not care.

Further theoretical impacts:

                if ((fp = fopen(DATA_MHEARD_FILE, "r+")) == NULL) {
                        if (logging)
                                syslog(LOG_ERR, "cannot open mheard data file\n");
                        continue;
                }

=> If the filesystem is temporarily full, the entry will be ommited.
If i.E. 3 new calls are heard, then the filesystem is filled, and then the next new call is heard, then

                  fseek(fp, mheard->position, SEEK_SET);

will make 3 gaps (nulled) and stores the new mheard struct entry.
The info of the 3 calls is lost. The file has gap entries. But since we always operate with seek, it doesn't matter at all.

Next potential problem:

                fwrite(&mheard->entry, sizeof(struct mheard_struct), 1, fp);

If fwrrite() cannot write the whole data (i.E. filesystem gets full during write, or if the hd has an error and the write times out during operation, then the appended length of data is shorter than sizeof(struct mheard_struct). Because we operate on blocks, all other data that is appended later is completely garbage (i.E. you expcect a callsignt but get statistic data at that position).

This could be corrected by changing

                if (mheard->position == 0xFFFFFF) {
                        fseek(fp, 0L, SEEK_END);
                        mheard->position = ftell(fp);
                }
to:
                if (mheard->position == 0xFFFFFF) {
                        fseek(fp, 0L, SEEK_END);
                        mheard->position = ftell(fp);
                        /* check for block offset error and align to */
			if ((mheard->position % sizeof(struct mheard_struct)) != 0)
                          mheard->position -= (mheard->position % sizeof(struct mheard_struct);
                }

Bernard, what do you think was the real cause for your corruptd data? I think it was a fail of ax25_validate() of the from/to call.

Thus I'd suggest to set
memset(&mheard->entry, 0x00, sizeof(struct mheard_struct)); mheard->in_use = FALSE;
before the "continue" statement in the validity checks for a received frame. This should avoid gaps.

Perhaps, we've not been successful to avoid all gaps. And the gaps really do not harm.

=> For mheard:
zero records have *from_call == \0.
incomplete records may have some other data not filled in. Because the mheardd does after filling all data sets the time
(time(&mheard->entry.last_heard);)
I argue, that this information is well enough to say, that it contains valid information.

That said, we're able to skip empty blocks during the file read in the mheard program:
currently:

        while (fread(&mheard, sizeof(struct mheard_struct), 1, fp) == 1) {
                pr = malloc(sizeof(struct PortRecord));
                pr->entry = mheard;
                pr->Next  = PortList;
                PortList  = pr;
        }

solution:

        while (fread(&mheard, sizeof(struct mheard_struct), 1, fp) == 1) {
		/* skip empty blocks */
		if (mheard->entry.last_heard == 0L)
		  continue;
                /* or, if you really like better this one: if (*mheard->from_call == '\0) continue; */
                pr = malloc(sizeof(struct PortRecord));
                pr->entry = mheard;
                pr->Next  = PortList;
                PortList  = pr;
        }

vy 73,
- Thomas dl9sau

To: [email protected]
Cc: Bernard F6BVP <[email protected]>

---
 include/net/rose.h    |    3 ++-
 net/rose/af_rose.c    |   11 ++++++-----
 net/rose/rose_in.c    |   13 +++++++------
 net/rose/rose_route.c |   26 ++++++++++++++------------
 net/rose/rose_timer.c |    3 ++-
 5 files changed, 31 insertions(+), 25 deletions(-)

index 0474a83..7578ed4 100644
@@ -7,6 +7,7 @@
 #ifndef _ROSE_H
 #define _ROSE_H 
 
+#include <linux/atomic.h>
 #include <linux/rose.h>
 #include <linux/spinlock.h>
 #include <net/sock.h>

@@ -95,7 +96,7 @@ struct rose_neigh {
 	ax25_cb			*ax25;
 	struct net_device		*dev;
 	unsigned short		count;
-	unsigned short		use;
+	atomic_t		use;
 	unsigned int		number;
 	char			restarted;
 	char			dce_mode;

index a339ea5..47f1824 100644
@@ -10,6 +10,7 @@
  * Copyright (C) Tomi Manninen OH2BNS ([email protected])
  */
 
+#include <linux/atomic.h>
 #include <linux/capability.h>
 #include <linux/module.h>
 #include <linux/moduleparam.h>

@@ -175,7 +176,7 @@ void rose_kill_by_neigh(struct rose_neigh *neigh)
 
 		if (rose->neighbour == neigh) {
 			rose_disconnect(s, ENETUNREACH, ROSE_OUT_OF_ORDER, 0);
-			rose->neighbour->use--;
+			atomic_dec(&rose->neighbour->use);
 			rose->neighbour = NULL;
 		}
 	}

@@ -196,7 +197,7 @@ static void rose_kill_by_device(struct net_device *dev)
 
 		if (rose->device == dev) {
 			rose_disconnect(s, ENETUNREACH, ROSE_OUT_OF_ORDER, 0);
-			rose->neighbour->use--;
+			atomic_dec(&rose->neighbour->use);
 			rose->device = NULL;
 		}
 	}

@@ -624,7 +625,7 @@ static int rose_release(struct socket *sock)
 		break;
 
 	case ROSE_STATE_2:
-		rose->neighbour->use--;
+		atomic_dec(&rose->neighbour->use);
 		release_sock(sk);
 		rose_disconnect(sk, 0, -1, -1);
 		lock_sock(sk);

@@ -823,7 +824,7 @@ static int rose_connect(struct socket *sock, struct sockaddr *uaddr, int addr_le
 
 	rose->state = ROSE_STATE_1;
 
-	rose->neighbour->use++;
+	atomic_inc(&rose->neighbour->use);
 
 	rose_write_internal(sk, ROSE_CALL_REQUEST);
 	rose_start_heartbeat(sk);

@@ -1023,7 +1024,7 @@ int rose_rx_call_request(struct sk_buff *skb, struct net_device *dev, struct ros
 	make_rose->device        = dev;
 	make_rose->facilities    = facilities;
 
-	make_rose->neighbour->use++;
+	atomic_inc(&make_rose->neighbour->use);
 
 	if (rose_sk(sk)->defer) {
 		make_rose->state = ROSE_STATE_5;

index 7f7fcb4..c62e08d 100644
@@ -11,6 +11,7 @@
  * but are mostly correct. Before you modify the code could you read the SDL
  * diagrams as the code is not obvious and probably very easy to break.
  */
+#include <linux/atomic.h>
 #include <linux/errno.h>
 #include <linux/types.h>
 #include <linux/socket.h>

@@ -59,7 +60,7 @@ static int rose_state1_machine(struct sock *sk, struct sk_buff *skb, int framety
 	case ROSE_CLEAR_REQUEST:
 		rose_write_internal(sk, ROSE_CLEAR_CONFIRMATION);
 		rose_disconnect(sk, ECONNREFUSED, skb->data[3], skb->data[4]);
-		rose->neighbour->use--;
+		atomic_dec(&rose->neighbour->use);
 		break;
 
 	default:

@@ -82,12 +83,12 @@ static int rose_state2_machine(struct sock *sk, struct sk_buff *skb, int framety
 	case ROSE_CLEAR_REQUEST:
 		rose_write_internal(sk, ROSE_CLEAR_CONFIRMATION);
 		rose_disconnect(sk, 0, skb->data[3], skb->data[4]);
-		rose->neighbour->use--;
+		atomic_dec(&rose->neighbour->use);
 		break;
 
 	case ROSE_CLEAR_CONFIRMATION:
 		rose_disconnect(sk, 0, -1, -1);
-		rose->neighbour->use--;
+		atomic_dec(&rose->neighbour->use);
 		break;
 
 	default:

@@ -123,7 +124,7 @@ static int rose_state3_machine(struct sock *sk, struct sk_buff *skb, int framety
 	case ROSE_CLEAR_REQUEST:
 		rose_write_internal(sk, ROSE_CLEAR_CONFIRMATION);
 		rose_disconnect(sk, 0, skb->data[3], skb->data[4]);
-		rose->neighbour->use--;
+		atomic_dec(&rose->neighbour->use);
 		break;
 
 	case ROSE_RR:

@@ -234,7 +235,7 @@ static int rose_state4_machine(struct sock *sk, struct sk_buff *skb, int framety
 	case ROSE_CLEAR_REQUEST:
 		rose_write_internal(sk, ROSE_CLEAR_CONFIRMATION);
 		rose_disconnect(sk, 0, skb->data[3], skb->data[4]);
-		rose->neighbour->use--;
+		atomic_dec(&rose->neighbour->use);
 		break;
 
 	default:

@@ -254,7 +255,7 @@ static int rose_state5_machine(struct sock *sk, struct sk_buff *skb, int framety
 	if (frametype == ROSE_CLEAR_REQUEST) {
 		rose_write_internal(sk, ROSE_CLEAR_CONFIRMATION);
 		rose_disconnect(sk, 0, skb->data[3], skb->data[4]);
-		rose_sk(sk)->neighbour->use--;
+		atomic_dec(&rose_sk(sk)->neighbour->use);
 	}
 
 	return 0;

index 479cae5..db6b96d 100644
@@ -7,6 +7,7 @@
  * Copyright (C) Jonathan Naylor G4KLX ([email protected])
  * Copyright (C) Terry Dawson VK2KTJ ([email protected])
  */
+#include <linux/atomic.h>
 #include <linux/errno.h>
 #include <linux/types.h>
 #include <linux/socket.h>

@@ -97,7 +98,7 @@ static int __must_check rose_add_node(struct rose_route_struct *rose_route,
 		rose_neigh->ax25      = NULL;
 		rose_neigh->dev       = dev;
 		rose_neigh->count     = 0;
-		rose_neigh->use       = 0;
+		atomic_set(&rose_neigh->use, 0);
 		rose_neigh->dce_mode  = 0;
 		rose_neigh->loopback  = 0;
 		rose_neigh->number    = rose_neigh_no++;

@@ -267,10 +268,10 @@ static void rose_remove_route(struct rose_route *rose_route)
 	struct rose_route *s;
 
 	if (rose_route->neigh1 != NULL)
-		rose_route->neigh1->use--;
+		atomic_dec(&rose_route->neigh1->use);
 
 	if (rose_route->neigh2 != NULL)
-		rose_route->neigh2->use--;
+		atomic_dec(&rose_route->neigh2->use);
 
 	if ((s = rose_route_list) == rose_route) {
 		rose_route_list = rose_route->next;

@@ -335,7 +336,8 @@ static int rose_del_node(struct rose_route_struct *rose_route,
 		if (rose_node->neighbour[i] == rose_neigh) {
 			rose_neigh->count--;
 
-			if (rose_neigh->count == 0 && rose_neigh->use == 0)
+			if (rose_neigh->count == 0 &&
+			    atomic_read(&rose_neigh->use) == 0)
 				rose_remove_neigh(rose_neigh);
 
 			rose_node->count--;

@@ -383,7 +385,7 @@ void rose_add_loopback_neigh(void)
 	sn->ax25      = NULL;
 	sn->dev       = NULL;
 	sn->count     = 0;
-	sn->use       = 0;
+	atomic_set(&sn->use, 0);
 	sn->dce_mode  = 1;
 	sn->loopback  = 1;
 	sn->number    = rose_neigh_no++;

@@ -573,7 +575,7 @@ static int rose_clear_routes(void)
 		s          = rose_neigh;
 		rose_neigh = rose_neigh->next;
 
-		if (s->use == 0 && !s->loopback) {
+		if (atomic_read(&s->use) == 0 && !s->loopback) {
 			s->count = 0;
 			rose_remove_neigh(s);
 		}

@@ -788,13 +790,13 @@ static void rose_del_route_by_neigh(struct rose_neigh *rose_neigh)
 		}
 
 		if (rose_route->neigh1 == rose_neigh) {
-			rose_route->neigh1->use--;
+			atomic_dec(&rose_route->neigh1->use);
 			rose_route->neigh1 = NULL;
 			rose_transmit_clear_request(rose_route->neigh2, rose_route->lci2, ROSE_OUT_OF_ORDER, 0);
 		}
 
 		if (rose_route->neigh2 == rose_neigh) {
-			rose_route->neigh2->use--;
+			atomic_dec(&rose_route->neigh2->use);
 			rose_route->neigh2 = NULL;
 			rose_transmit_clear_request(rose_route->neigh1, rose_route->lci1, ROSE_OUT_OF_ORDER, 0);
 		}

@@ -923,7 +925,7 @@ int rose_route_frame(struct sk_buff *skb, ax25_cb *ax25)
 			rose_clear_queues(sk);
 			rose->cause	 = ROSE_NETWORK_CONGESTION;
 			rose->diagnostic = 0;
-			rose->neighbour->use--;
+			atomic_dec(&rose->neighbour->use);
 			rose->neighbour	 = NULL;
 			rose->lci	 = 0;
 			rose->state	 = ROSE_STATE_0;

@@ -1066,8 +1068,8 @@ int rose_route_frame(struct sk_buff *skb, ax25_cb *ax25)
 	rose_route->lci2      = new_lci;
 	rose_route->neigh2    = new_neigh;
 
-	rose_route->neigh1->use++;
-	rose_route->neigh2->use++;
+	atomic_inc(&rose_route->neigh1->use);
+	atomic_inc(&rose_route->neigh2->use);
 
 	rose_route->next = rose_route_list;
 	rose_route_list  = rose_route;

@@ -1214,7 +1216,7 @@ static int rose_neigh_show(struct seq_file *seq, void *v)
 			   (rose_neigh->loopback) ? "RSLOOP-0" : ax2asc(buf, &rose_neigh->callsign),
 			   rose_neigh->dev ? rose_neigh->dev->name : "???",
 			   rose_neigh->count,
-			   rose_neigh->use,
+			   atomic_read(&rose_neigh->use),
 			   (rose_neigh->dce_mode) ? "DCE" : "DTE",
 			   (rose_neigh->restarted) ? "yes" : "no",
 			   ax25_display_timer(&rose_neigh->t0timer) / HZ,

index b6c8f38..4c09202 100644
@@ -7,6 +7,7 @@
  * Copyright (C) Jonathan Naylor G4KLX ([email protected])
  * Copyright (C) 2002 Ralf Baechle DO1GRB ([email protected])
  */
+#include <linux/atomic.h>
 #include <linux/errno.h>
 #include <linux/types.h>
 #include <linux/socket.h>

@@ -179,7 +180,7 @@ static void rose_timer_expiry(unsigned long param)
 		break;
 
 	case ROSE_STATE_2:	/* T3 */
-		rose->neighbour->use--;
+		atomic_dec(&rose->neighbour->use);
 		rose_disconnect(sk, ETIMEDOUT, -1, -1);
 		break;
 

1.7.4.4

To: [email protected]
Cc: Bernard F6BVP <[email protected]>

---
 net/rose/rose_route.c |    6 +++---
 1 files changed, 3 insertions(+), 3 deletions(-)

index db6b96d..7e90412 100644
@@ -38,7 +38,7 @@
 #include <net/rose.h>
 #include <linux/seq_file.h>
 
-static unsigned int rose_neigh_no = 1;
+static atomic_t rose_neigh_no = ATOMIC_INIT(0);
 
 static struct rose_node  *rose_node_list;
 static DEFINE_SPINLOCK(rose_node_list_lock);

@@ -101,7 +101,7 @@ static int __must_check rose_add_node(struct rose_route_struct *rose_route,
 		atomic_set(&rose_neigh->use, 0);
 		rose_neigh->dce_mode  = 0;
 		rose_neigh->loopback  = 0;
-		rose_neigh->number    = rose_neigh_no++;
+		rose_neigh->number    = atomic_inc_return(rose_neigh_no);
 		rose_neigh->restarted = 0;
 
 		skb_queue_head_init(&rose_neigh->queue);

@@ -388,7 +388,7 @@ void rose_add_loopback_neigh(void)
 	atomic_set(&sn->use, 0);
 	sn->dce_mode  = 1;
 	sn->loopback  = 1;
-	sn->number    = rose_neigh_no++;
+	sn->number    = atomic_inc_return(rose_neigh_no);
 	sn->restarted = 1;
 
 	skb_queue_head_init(&sn->queue);

1.7.4.4

---
This patch fixes the build error introduced by the first patch.

 net/rose/rose_route.c |    6 +++---
 1 files changed, 3 insertions(+), 3 deletions(-)

index db6b96d..18e7d00 100644
@@ -38,7 +38,7 @@
 #include <net/rose.h>
 #include <linux/seq_file.h>
 
-static unsigned int rose_neigh_no = 1;
+static atomic_t rose_neigh_no = ATOMIC_INIT(0);
 
 static struct rose_node  *rose_node_list;
 static DEFINE_SPINLOCK(rose_node_list_lock);

@@ -101,7 +101,7 @@ static int __must_check rose_add_node(struct rose_route_struct *rose_route,
 		atomic_set(&rose_neigh->use, 0);
 		rose_neigh->dce_mode  = 0;
 		rose_neigh->loopback  = 0;
-		rose_neigh->number    = rose_neigh_no++;
+		rose_neigh->number    = atomic_inc_return(&rose_neigh_no);
 		rose_neigh->restarted = 0;
 
 		skb_queue_head_init(&rose_neigh->queue);

@@ -388,7 +388,7 @@ void rose_add_loopback_neigh(void)
 	atomic_set(&sn->use, 0);
 	sn->dce_mode  = 1;
 	sn->loopback  = 1;
-	sn->number    = rose_neigh_no++;
+	sn->number    = atomic_inc_return(&rose_neigh_no);
 	sn->restarted = 1;
 
 	skb_queue_head_init(&sn->queue);

To: [email protected]
Cc: Bernard F6BVP <[email protected]>

---
 net/rose/af_rose.c   |    7 +++++--
 net/rose/rose_subr.c |    3 ++-
 2 files changed, 7 insertions(+), 3 deletions(-)

index 47f1824..2e058bb 100644
@@ -609,7 +609,8 @@ static int rose_release(struct socket *sock)
 	struct sock *sk = sock->sk;
 	struct rose_sock *rose;
 
-	if (sk == NULL) return 0;
+	if (sk == NULL)
+		return 0;
 
 	sock_hold(sk);
 	sock_orphan(sk);

@@ -1353,7 +1354,9 @@ static int rose_ioctl(struct socket *sock, unsigned int cmd, unsigned long arg)
 	}
 
 	case SIOCRSSL2CALL:
-		if (!capable(CAP_NET_ADMIN)) return -EPERM;
+		if (!capable(CAP_NET_ADMIN))
+			return -EPERM;
+
 		if (ax25cmp(&rose_callsign, &null_ax25_address) != 0)
 			ax25_listen_release(&rose_callsign, NULL);
 		if (copy_from_user(&tmp_call, argp, sizeof(ax25_address)))

index f6c71ca..53fb653 100644
@@ -89,7 +89,8 @@ int rose_validate_nr(struct sock *sk, unsigned short nr)
 	unsigned short vc = rose->va;
 
 	while (vc != rose->vs) {
-		if (nr == vc) return 1;
+		if (nr == vc)
+			return 1;
 		vc = (vc + 1) % ROSE_MODULUS;
 	}
 

1.7.4.4

To: [email protected]
Cc: Bernard F6BVP <[email protected]>

---
 include/net/rose.h |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)

index 7578ed4..d2ebf13 100644
@@ -94,7 +94,7 @@ struct rose_neigh {
 	ax25_address		callsign;
 	ax25_digi		*digipeat;
 	ax25_cb			*ax25;
-	struct net_device		*dev;
+	struct net_device	*dev;
 	unsigned short		count;
 	atomic_t		use;
 	unsigned int		number;

1.7.4.4

Hello Ralf,

All seven patch applied.
However there are compile errors in rose_route.c

f6bvp-8 linux]# make modules
CHK include/linux/version.h
CHK include/generated/utsrelease.h
CALL scripts/checksyscalls.sh
CC [M] net/rose/af_rose.o
CC [M] net/rose/rose_dev.o
CC [M] net/rose/rose_in.o
CC [M] net/rose/rose_link.o
CC [M] net/rose/rose_loopback.o
CC [M] net/rose/rose_out.o
CC [M] net/rose/rose_route.o
net/rose/rose_route.c: In function ‘rose_add_node’:
net/rose/rose_route.c:104: erreur: incompatible type for argument 2 of ‘atomic_add_return’ /usr/src/linux-2.6.39/arch/x86/include/asm/atomic.h:173: note: expected ‘struct atomic_t *’ but argument is of type ‘atomic_t’ net/rose/rose_route.c: In function ‘rose_add_loopback_neigh’:
net/rose/rose_route.c:391: erreur: incompatible type for argument 2 of ‘atomic_add_return’ /usr/src/linux-2.6.39/arch/x86/include/asm/atomic.h:173: note: expected ‘struct atomic_t *’ but argument is of type ‘atomic_t’ make[2]: *** [net/rose/rose_route.o] Erreur 1
make[1]: *** [net/rose] Erreur 2
make: *** [net] Erreur 2

73 de Bernard, f6bvp

--
To unsubscribe from this list: send the line "unsubscribe linux-hams" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

Odd, the timestamps of my build tree must have been scrambled. I get the same error messages but only after a full make clean and the error is quite obvious.

I'm going to send a replacement match for the defective patch in a minute.

Ralf
--
To unsubscribe from this list: send the line "unsubscribe linux-hams" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

Hello Ralf,

Replacement patch applied and install went fine.
Nearly 24 hours after running the new "atomic" rose code
on two systems, I observe that 'use' parameter is 0, something I never observed before. It used to be positive on some link and rarely displaying a high number meaning underflow negative values.

I guess this is a pretty good thing.

I will try removing rose module and report if any progress on that point too.

Bernard

--
To unsubscribe from this list: send the line "unsubscribe linux-hams" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

Most excellent! Take your time for testing - unfortunately we missed the v3.0 train already but it would be great if we could backport these fixes to -stable after some more positive testing.

Is the system that was having these issues btw. running a preemptable kernel or does it have multiple cores or hyperthreading?

Thanks,

Ralf

On one Linux box system I have a dual core CPU and kernel was compiled with Symmetric multi-processing support. [*] Symmetric multi-processing support
However I am booting kernel with maxcpus=1 in order to keep this test system as "simple" as possible. As I am not sure if that may influence hyperthreading or not I attach here info.log file displaying my last boot log. I did not enabled Hyperthreading
[ ] SMT (Hyperthreading) scheduler support and
(X) No Forced Preemption (Server)
This one shows the new 0 value for use parameter except for RSLOOP-0 as shown previously.

On my other Linux box there is an Intel Core 2 CPU and kernel was also compiled with SMP support, no SMT hyperthreading, Multi-core scheduler support enabled and Voluntary Kernel Preemption (Desktop) enabled.
This one has no special boot instructions, and thus runs with two CPUs enabled
and /proc/net/rose_neigh table also shows use parameter = 0 except for RSLOOP-0.

Bernard

/var/log/kernel/info.log

Jul 20 22:04:06 f6bvp-11 kernel: imklog 4.6.2, log source = /proc/kmsg started.
Jul 20 22:04:06 f6bvp-11 kernel: Initializing cgroup subsys cpuset
Jul 20 22:04:06 f6bvp-11 kernel: Linux version 2.6.39.3 (root@f6bvp-10) (gcc version 4.4.3 (GCC) ) #4 SMP Mon Jul 11 18:27:23 CEST 2011
Jul 20 22:04:06 f6bvp-11 kernel: Command line: BOOT_IMAGE=2.6.39.3 root=UUID=2a98cbcc-9db7-442c-a308-fc1a37dc693e pci=use_crs maxcpus=1 splash=silent resume=UUID=fbb4a76a-7d96-465a-bcf3-54b42027a836 vga=788
Jul 20 22:04:06 f6bvp-11 kernel: BIOS-provided physical RAM map:
Jul 20 22:04:06 f6bvp-11 kernel: BIOS-e820: 0000000000000000 - 000000000009f000 (usable)
Jul 20 22:04:06 f6bvp-11 kernel: BIOS-e820: 000000000009f000 - 00000000000a0000 (reserved)
Jul 20 22:04:06 f6bvp-11 kernel: BIOS-e820: 00000000000f0000 - 0000000000100000 (reserved)
Jul 20 22:04:06 f6bvp-11 kernel: BIOS-e820: 0000000000100000 - 000000007fee0000 (usable)
Jul 20 22:04:06 f6bvp-11 kernel: BIOS-e820: 000000007fee0000 - 000000007fee3000 (ACPI NVS)
Jul 20 22:04:06 f6bvp-11 kernel: BIOS-e820: 000000007fee3000 - 000000007fef0000 (ACPI data)
Jul 20 22:04:06 f6bvp-11 kernel: BIOS-e820: 00000000e0000000 - 00000000f0000000 (reserved)
Jul 20 22:04:06 f6bvp-11 kernel: BIOS-e820: 00000000fec00000 - 0000000100000000 (reserved)
Jul 20 22:04:06 f6bvp-11 kernel: NX (Execute Disable) protection: active
Jul 20 22:04:06 f6bvp-11 kernel: DMI 2.3 present.
Jul 20 22:04:06 f6bvp-11 kernel: DMI: MICRO-STAR INTERNATIONAL CO., LTD MS-7258/MS-7258, BIOS V3.9 07/16/2007
Jul 20 22:04:06 f6bvp-11 kernel: e820 update range: 0000000000000000 - 0000000000010000 (usable) ==> (reserved)
Jul 20 22:04:06 f6bvp-11 kernel: e820 remove range: 00000000000a0000 - 0000000000100000 (usable)
Jul 20 22:04:06 f6bvp-11 kernel: last_pfn = 0x7fee0 max_arch_pfn = 0x400000000
Jul 20 22:04:06 f6bvp-11 kernel: MTRR default type: uncachable
Jul 20 22:04:06 f6bvp-11 kernel: MTRR fixed ranges enabled:
Jul 20 22:04:06 f6bvp-11 kernel:  00000-9FFFF write-back
Jul 20 22:04:06 f6bvp-11 kernel:  A0000-BFFFF uncachable
Jul 20 22:04:06 f6bvp-11 kernel:  C0000-CDFFF write-protect
Jul 20 22:04:06 f6bvp-11 kernel:  CE000-EFFFF uncachable
Jul 20 22:04:06 f6bvp-11 kernel:  F0000-F7FFF write-through
Jul 20 22:04:06 f6bvp-11 kernel:  F8000-F8FFF uncachable
Jul 20 22:04:06 f6bvp-11 kernel:  F9000-FFFFF write-through
Jul 20 22:04:06 f6bvp-11 kernel: MTRR variable ranges enabled:
Jul 20 22:04:06 f6bvp-11 kernel:  0 base 000000000 mask F80000000 write-back
Jul 20 22:04:06 f6bvp-11 kernel:  1 base 0D0000000 mask FF8000000 write-combining
Jul 20 22:04:06 f6bvp-11 kernel:  2 base 07FF00000 mask FFFF00000 uncachable
Jul 20 22:04:06 f6bvp-11 kernel:  3 disabled
Jul 20 22:04:06 f6bvp-11 kernel:  4 disabled
Jul 20 22:04:06 f6bvp-11 kernel:  5 disabled
Jul 20 22:04:06 f6bvp-11 kernel:  6 disabled
Jul 20 22:04:06 f6bvp-11 kernel:  7 disabled
Jul 20 22:04:06 f6bvp-11 kernel: x86 PAT enabled: cpu 0, old 0x7040600070406, new 0x7010600070106
Jul 20 22:04:06 f6bvp-11 kernel: found SMP MP-table at [ffff8800000f39c0] f39c0
Jul 20 22:04:06 f6bvp-11 kernel: initial memory mapped : 0 - 20000000
Jul 20 22:04:06 f6bvp-11 kernel: Base memory trampoline at [ffff88000009a000] 9a000 size 20480
Jul 20 22:04:06 f6bvp-11 kernel: init_memory_mapping: 0000000000000000-000000007fee0000
Jul 20 22:04:06 f6bvp-11 kernel: 0000000000 - 007fe00000 page 2M
Jul 20 22:04:06 f6bvp-11 kernel: 007fe00000 - 007fee0000 page 4k
Jul 20 22:04:06 f6bvp-11 kernel: kernel direct mapping tables up to 7fee0000 @ 7fedc000-7fee0000
Jul 20 22:04:06 f6bvp-11 kernel: RAMDISK: 37ab4000 - 37ff0000
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: Local APIC address 0xfee00000
Jul 20 22:04:06 f6bvp-11 kernel: No NUMA configuration found
Jul 20 22:04:06 f6bvp-11 kernel: Faking a node at 0000000000000000-000000007fee0000
Jul 20 22:04:06 f6bvp-11 kernel: NUMA: Using 63 for the hash shift.
Jul 20 22:04:06 f6bvp-11 kernel: Initmem setup node 0 0000000000000000-000000007fee0000
Jul 20 22:04:06 f6bvp-11 kernel:  NODE_DATA [000000007fed7000 - 000000007fedbfff]
Jul 20 22:04:06 f6bvp-11 kernel: [ffffea0000000000-ffffea0001bfffff] PMD -> [ffff88007d600000-ffff88007f1fffff] on node 0
Jul 20 22:04:06 f6bvp-11 kernel: On node 0 totalpages: 523887
Jul 20 22:04:06 f6bvp-11 kernel:  DMA zone: 56 pages used for memmap
Jul 20 22:04:06 f6bvp-11 kernel:  DMA zone: 5 pages reserved
Jul 20 22:04:06 f6bvp-11 kernel:  DMA zone: 3922 pages, LIFO batch:0
Jul 20 22:04:06 f6bvp-11 kernel:  DMA32 zone: 7109 pages used for memmap
Jul 20 22:04:06 f6bvp-11 kernel:  DMA32 zone: 512795 pages, LIFO batch:31
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: PM-Timer IO Port: 0x408
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: Local APIC address 0xfee00000
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: LAPIC (acpi_id[0x00] lapic_id[0x00] enabled)
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: LAPIC (acpi_id[0x01] lapic_id[0x01] enabled)
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: LAPIC (acpi_id[0x02] lapic_id[0x02] disabled)
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: LAPIC (acpi_id[0x03] lapic_id[0x03] disabled)
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: LAPIC_NMI (acpi_id[0x00] high edge lint[0x1])
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: LAPIC_NMI (acpi_id[0x01] high edge lint[0x1])
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: LAPIC_NMI (acpi_id[0x02] high edge lint[0x1])
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: LAPIC_NMI (acpi_id[0x03] high edge lint[0x1])
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: IOAPIC (id[0x04] address[0xfec00000] gsi_base[0])
Jul 20 22:04:06 f6bvp-11 kernel: IOAPIC[0]: apic_id 4, version 3, address 0xfec00000, GSI 0-23
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: IOAPIC (id[0x05] address[0xfecc0000] gsi_base[24])
Jul 20 22:04:06 f6bvp-11 kernel: IOAPIC[1]: apic_id 5, version 3, address 0xfecc0000, GSI 24-47
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 low level)
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: IRQ0 used by override.
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: IRQ2 used by override.
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: IRQ9 used by override.
Jul 20 22:04:06 f6bvp-11 kernel: Using ACPI (MADT) for SMP configuration information
Jul 20 22:04:06 f6bvp-11 kernel: SMP: Allowing 4 CPUs, 2 hotplug CPUs
Jul 20 22:04:06 f6bvp-11 kernel: nr_irqs_gsi: 64
Jul 20 22:04:06 f6bvp-11 kernel: PM: Registered nosave memory: 000000000009f000 - 00000000000a0000
Jul 20 22:04:06 f6bvp-11 kernel: PM: Registered nosave memory: 00000000000a0000 - 00000000000f0000
Jul 20 22:04:06 f6bvp-11 kernel: PM: Registered nosave memory: 00000000000f0000 - 0000000000100000
Jul 20 22:04:06 f6bvp-11 kernel: Allocating PCI resources starting at 7fef0000 (gap: 7fef0000:60110000)
Jul 20 22:04:06 f6bvp-11 kernel: Booting paravirtualized kernel on bare hardware
Jul 20 22:04:06 f6bvp-11 kernel: setup_percpu: NR_CPUS:8 nr_cpumask_bits:8 nr_cpu_ids:4 nr_node_ids:1
Jul 20 22:04:06 f6bvp-11 kernel: PERCPU: Embedded 28 pages/cpu @ffff88007fc00000 s82240 r8192 d24256 u524288
Jul 20 22:04:06 f6bvp-11 kernel: pcpu-alloc: s82240 r8192 d24256 u524288 alloc=1*2097152
Jul 20 22:04:06 f6bvp-11 kernel: pcpu-alloc: [0] 0 1 2 3 
Jul 20 22:04:06 f6bvp-11 kernel: Kernel command line: BOOT_IMAGE=2.6.39.3 root=UUID=2a98cbcc-9db7-442c-a308-fc1a37dc693e pci=use_crs maxcpus=1 splash=silent resume=UUID=fbb4a76a-7d96-465a-bcf3-54b42027a836 vga=788
Jul 20 22:04:06 f6bvp-11 kernel: PID hash table entries: 4096 (order: 3, 32768 bytes)
Jul 20 22:04:06 f6bvp-11 kernel: Memory: 2053524k/2096000k available (3975k kernel code, 452k absent, 42024k reserved, 2039k data, 632k init)
Jul 20 22:04:06 f6bvp-11 kernel: SLUB: Genslabs=15, HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
Jul 20 22:04:06 f6bvp-11 kernel: Hierarchical RCU implementation.
Jul 20 22:04:06 f6bvp-11 kernel: 	RCU-based detection of stalled CPUs is disabled.
Jul 20 22:04:06 f6bvp-11 kernel: NR_IRQS:512
Jul 20 22:04:06 f6bvp-11 kernel: Console: colour dummy device 80x25
Jul 20 22:04:06 f6bvp-11 kernel: console [tty0] enabled
Jul 20 22:04:06 f6bvp-11 kernel: Calibrating delay loop (skipped), value calculated using timer frequency.. 4388.58 BogoMIPS (lpj=8777160)
Jul 20 22:04:06 f6bvp-11 kernel: pid_max: default: 32768 minimum: 301
Jul 20 22:04:06 f6bvp-11 kernel: Security Framework initialized
Jul 20 22:04:06 f6bvp-11 kernel: Dentry cache hash table entries: 262144 (order: 9, 2097152 bytes)
Jul 20 22:04:06 f6bvp-11 kernel: Inode-cache hash table entries: 131072 (order: 8, 1048576 bytes)
Jul 20 22:04:06 f6bvp-11 kernel: Mount-cache hash table entries: 256
Jul 20 22:04:06 f6bvp-11 kernel: Initializing cgroup subsys ns
Jul 20 22:04:06 f6bvp-11 kernel: Initializing cgroup subsys cpuacct
Jul 20 22:04:06 f6bvp-11 kernel: CPU: Physical Processor ID: 0
Jul 20 22:04:06 f6bvp-11 kernel: CPU: Processor Core ID: 0
Jul 20 22:04:06 f6bvp-11 kernel: mce: CPU supports 6 MCE banks
Jul 20 22:04:06 f6bvp-11 kernel: CPU0: Thermal monitoring enabled (TM1)
Jul 20 22:04:06 f6bvp-11 kernel: using mwait in idle threads.
Jul 20 22:04:06 f6bvp-11 kernel: SMP alternatives: switching to UP code
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: Core revision 20110316
Jul 20 22:04:06 f6bvp-11 kernel: Setting APIC routing to flat
Jul 20 22:04:06 f6bvp-11 kernel: ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
Jul 20 22:04:06 f6bvp-11 kernel: CPU0: Intel(R) Core(TM)2 Duo CPU     E4500  @ 2.20GHz stepping 0d
Jul 20 22:04:06 f6bvp-11 kernel: Performance Events: PEBS fmt0+, Core2 events, Intel PMU driver.
Jul 20 22:04:06 f6bvp-11 kernel: ... version:                2
Jul 20 22:04:06 f6bvp-11 kernel: ... bit width:              40
Jul 20 22:04:06 f6bvp-11 kernel: ... generic registers:      2
Jul 20 22:04:06 f6bvp-11 kernel: ... value mask:             000000ffffffffff
Jul 20 22:04:06 f6bvp-11 kernel: ... max period:             000000007fffffff
Jul 20 22:04:06 f6bvp-11 kernel: ... fixed-purpose events:   3
Jul 20 22:04:06 f6bvp-11 kernel: ... event mask:             0000000700000003
Jul 20 22:04:06 f6bvp-11 kernel: Brought up 1 CPUs
Jul 20 22:04:06 f6bvp-11 kernel: Total of 1 processors activated (4388.58 BogoMIPS).
Jul 20 22:04:06 f6bvp-11 kernel: PM: Registering ACPI NVS region at 7fee0000 (12288 bytes)
Jul 20 22:04:06 f6bvp-11 kernel: NET: Registered protocol family 16
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: bus type pci registered
Jul 20 22:04:06 f6bvp-11 kernel: PCI: MMCONFIG for domain 0000 [bus 00-ff] at [mem 0xe0000000-0xefffffff] (base 0xe0000000)
Jul 20 22:04:06 f6bvp-11 kernel: PCI: MMCONFIG at [mem 0xe0000000-0xefffffff] reserved in E820
Jul 20 22:04:06 f6bvp-11 kernel: PCI: Using configuration type 1 for base access
Jul 20 22:04:06 f6bvp-11 kernel: bio: create slab <bio-0> at 0
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: EC: Look up EC in DSDT
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: Interpreter enabled
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: (supports S0 S1 S4 S5)
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: Using IOAPIC for interrupt routing
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: No dock devices found.
Jul 20 22:04:06 f6bvp-11 kernel: PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
Jul 20 22:04:06 f6bvp-11 kernel: pci_root PNP0A08:00: host bridge window [io  0x0000-0x0cf7]
Jul 20 22:04:06 f6bvp-11 kernel: pci_root PNP0A08:00: host bridge window [io  0x0d00-0xffff]
Jul 20 22:04:06 f6bvp-11 kernel: pci_root PNP0A08:00: host bridge window [mem 0x000a0000-0x000bffff]
Jul 20 22:04:06 f6bvp-11 kernel: pci_root PNP0A08:00: host bridge window [mem 0x000c0000-0x000dffff]
Jul 20 22:04:06 f6bvp-11 kernel: pci_root PNP0A08:00: host bridge window [mem 0x7ff00000-0xfebfffff]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:00.0: [1106:0327] type 0 class 0x000600
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:00.0: reg 10: [mem 0xd0000000-0xd7ffffff pref]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:00.1: [1106:1327] type 0 class 0x000600
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:00.2: [1106:2327] type 0 class 0x000600
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:00.3: [1106:3327] type 0 class 0x000600
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:00.4: [1106:4327] type 0 class 0x000600
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:00.5: [1106:5327] type 0 class 0x000800
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:00.6: [1106:6327] type 0 class 0x000600
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:00.7: [1106:7327] type 0 class 0x000600
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:01.0: [1106:b198] type 1 class 0x000604
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:02.0: [1106:a327] type 1 class 0x000604
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:02.0: PME# supported from D0 D3hot D3cold
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:02.0: PME# disabled
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:03.0: [1106:c327] type 1 class 0x000604
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:03.0: PME# supported from D0 D3hot D3cold
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:03.0: PME# disabled
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:0b.0: [10ec:8139] type 0 class 0x000200
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:0b.0: reg 10: [io  0xfc00-0xfcff]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:0b.0: reg 14: [mem 0xdffff000-0xdffff0ff]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:0b.0: supports D1 D2
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:0b.0: PME# supported from D1 D2 D3hot D3cold
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:0b.0: PME# disabled
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:0f.0: [1106:3149] type 0 class 0x000101
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:0f.0: reg 10: [io  0xf800-0xf807]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:0f.0: reg 14: [io  0xf400-0xf403]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:0f.0: reg 18: [io  0xf000-0xf007]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:0f.0: reg 1c: [io  0xec00-0xec03]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:0f.0: reg 20: [io  0xe800-0xe80f]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:0f.0: reg 24: [io  0xe400-0xe4ff]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:0f.1: [1106:0571] type 0 class 0x000101
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:0f.1: reg 20: [io  0xe000-0xe00f]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:10.0: [1106:3038] type 0 class 0x000c03
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:10.0: reg 20: [io  0xdc00-0xdc1f]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:10.0: supports D1 D2
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:10.0: PME# supported from D0 D1 D2 D3hot D3cold
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:10.0: PME# disabled
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:10.1: [1106:3038] type 0 class 0x000c03
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:10.1: reg 20: [io  0xd800-0xd81f]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:10.1: supports D1 D2
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:10.1: PME# supported from D0 D1 D2 D3hot D3cold
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:10.1: PME# disabled
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:10.2: [1106:3038] type 0 class 0x000c03
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:10.2: reg 20: [io  0xd400-0xd41f]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:10.2: supports D1 D2
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:10.2: PME# supported from D0 D1 D2 D3hot D3cold
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:10.2: PME# disabled
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:10.3: [1106:3038] type 0 class 0x000c03
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:10.3: reg 20: [io  0xd000-0xd01f]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:10.3: supports D1 D2
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:10.3: PME# supported from D0 D1 D2 D3hot D3cold
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:10.3: PME# disabled
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:10.4: [1106:3104] type 0 class 0x000c03
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:10.4: reg 10: [mem 0xdfffe000-0xdfffe0ff]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:10.4: supports D1 D2
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:10.4: PME# supported from D0 D1 D2 D3hot D3cold
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:10.4: PME# disabled
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:11.0: [1106:3227] type 0 class 0x000601
Jul 20 22:04:06 f6bvp-11 kernel: HPET not enabled in BIOS. You might try hpet=force boot option
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:11.5: [1106:3059] type 0 class 0x000401
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:11.5: reg 10: [io  0xcc00-0xccff]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:11.5: supports D1 D2
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:01.0: PCI bridge to [bus 01-01]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:01.0:   bridge window [io  0x9000-0x9fff]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:01.0:   bridge window [mem 0xdfc00000-0xdfcfffff]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:01.0:   bridge window [mem 0xdfb00000-0xdfbfffff pref]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:02:00.0: [10de:0392] type 0 class 0x000300
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:02:00.0: reg 10: [mem 0xdc000000-0xdcffffff]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:02:00.0: reg 14: [mem 0xc0000000-0xcfffffff 64bit pref]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:02:00.0: reg 1c: [mem 0xdd000000-0xddffffff 64bit]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:02:00.0: reg 24: [io  0xbc00-0xbc7f]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:02:00.0: reg 30: [mem 0x00000000-0x0001ffff pref]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:02:00.0: disabling ASPM on pre-1.1 PCIe device.  You can enable it with 'pcie_aspm=force'
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:02.0: PCI bridge to [bus 02-02]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:02.0:   bridge window [io  0xb000-0xbfff]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:02.0:   bridge window [mem 0xdc000000-0xdeffffff]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:02.0:   bridge window [mem 0xc0000000-0xcfffffff 64bit pref]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:03.0: PCI bridge to [bus 03-03]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:03.0:   bridge window [io  0xa000-0xafff]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:03.0:   bridge window [mem 0xdfe00000-0xdfefffff]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:03.0:   bridge window [mem 0xdfd00000-0xdfdfffff 64bit pref]
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: PCI Interrupt Routing Table [\_SB_.PCI0._PRT]
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.PEXG._PRT]
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.PEX0._PRT]
Jul 20 22:04:06 f6bvp-11 kernel: pci0000:00: Requesting ACPI _OSC control (0x1d)
Jul 20 22:04:06 f6bvp-11 kernel: Unable to assume _OSC PCIe control. Disabling ASPM
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: PCI Interrupt Link [LNKA] (IRQs 3 4 6 7 *10 11 12)
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: PCI Interrupt Link [LNKB] (IRQs 3 4 6 7 10 *11 12)
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: PCI Interrupt Link [LNKC] (IRQs 3 4 6 7 10 *11 12)
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: PCI Interrupt Link [LNKD] (IRQs 3 4 6 7 10 11 12) *0, disabled.
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: PCI Interrupt Link [LNKE] (IRQs 3 4 6 7 10 11 12) *0, disabled.
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: PCI Interrupt Link [LNKF] (IRQs 3 4 6 7 10 11 12) *0
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: PCI Interrupt Link [LNK0] (IRQs 3 4 6 7 10 11 12) *0, disabled.
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: PCI Interrupt Link [LNK1] (IRQs 3 4 6 7 10 11 12) *5
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: PCI Interrupt Link [ALKA] (IRQs *20)
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: PCI Interrupt Link [ALKB] (IRQs *21)
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: PCI Interrupt Link [ALKC] (IRQs *22)
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: PCI Interrupt Link [ALKD] (IRQs *23), disabled.
Jul 20 22:04:06 f6bvp-11 kernel: vgaarb: device added: PCI:0000:02:00.0,decodes=io+mem,owns=io+mem,locks=none
Jul 20 22:04:06 f6bvp-11 kernel: vgaarb: loaded
Jul 20 22:04:06 f6bvp-11 kernel: PCI: Using ACPI for IRQ routing
Jul 20 22:04:06 f6bvp-11 kernel: PCI: pci_cache_line_size set to 64 bytes
Jul 20 22:04:06 f6bvp-11 kernel: reserve RAM buffer: 000000000009f000 - 000000000009ffff 
Jul 20 22:04:06 f6bvp-11 kernel: reserve RAM buffer: 000000007fee0000 - 000000007fffffff 
Jul 20 22:04:06 f6bvp-11 kernel: NetLabel: Initializing
Jul 20 22:04:06 f6bvp-11 kernel: NetLabel:  domain hash size = 128
Jul 20 22:04:06 f6bvp-11 kernel: NetLabel:  protocols = UNLABELED CIPSOv4
Jul 20 22:04:06 f6bvp-11 kernel: NetLabel:  unlabeled traffic allowed by default
Jul 20 22:04:06 f6bvp-11 kernel: pnp: PnP ACPI init
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: bus type pnp registered
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:00: [bus 00-ff]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:00: [io  0x0cf8-0x0cff]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:00: [io  0x0000-0x0cf7 window]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:00: [io  0x0d00-0xffff window]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:00: [mem 0x000a0000-0x000bffff window]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:00: [mem 0x000c0000-0x000dffff window]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:00: [mem 0x7ff00000-0xfebfffff window]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:00: Plug and Play ACPI device, IDs PNP0a08 PNP0a03 (active)
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:01: [io  0x0400-0x047f]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:01: [io  0x0500-0x050f]
Jul 20 22:04:06 f6bvp-11 kernel: system 00:01: [io  0x0400-0x047f] has been reserved
Jul 20 22:04:06 f6bvp-11 kernel: system 00:01: [io  0x0500-0x050f] has been reserved
Jul 20 22:04:06 f6bvp-11 kernel: system 00:01: Plug and Play ACPI device, IDs PNP0c02 (active)
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:02: [io  0x0010-0x001f]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:02: [io  0x0022-0x003f]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:02: [io  0x0044-0x005f]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:02: [io  0x0062-0x0063]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:02: [io  0x0065-0x006f]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:02: [io  0x0074-0x007f]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:02: [io  0x0091-0x0093]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:02: [io  0x00a2-0x00bf]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:02: [io  0x00e0-0x00ef]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:02: [io  0x04d0-0x04d1]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:02: [io  0x0290-0x0297]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:02: [io  0x0880-0x088f]
Jul 20 22:04:06 f6bvp-11 kernel: system 00:02: [io  0x04d0-0x04d1] has been reserved
Jul 20 22:04:06 f6bvp-11 kernel: system 00:02: [io  0x0290-0x0297] has been reserved
Jul 20 22:04:06 f6bvp-11 kernel: system 00:02: [io  0x0880-0x088f] has been reserved
Jul 20 22:04:06 f6bvp-11 kernel: system 00:02: Plug and Play ACPI device, IDs PNP0c02 (active)
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:03: [dma 4]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:03: [io  0x0000-0x000f]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:03: [io  0x0080-0x0090]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:03: [io  0x0094-0x009f]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:03: [io  0x00c0-0x00df]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:03: Plug and Play ACPI device, IDs PNP0200 (active)
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:04: [io  0x0070-0x0073]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:04: [irq 8]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:04: Plug and Play ACPI device, IDs PNP0b00 (active)
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:05: [io  0x0061]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:05: Plug and Play ACPI device, IDs PNP0800 (active)
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:06: [io  0x00f0-0x00ff]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:06: [irq 13]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:06: Plug and Play ACPI device, IDs PNP0c04 (active)
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:07: [io  0x03f0-0x03f5]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:07: [io  0x03f7]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:07: [irq 6]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:07: [dma 2]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:07: Plug and Play ACPI device, IDs PNP0700 (active)
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:08: [io  0x03f8-0x03ff]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:08: [irq 4]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:08: Plug and Play ACPI device, IDs PNP0501 (active)
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:09: [io  0x02f8-0x02ff]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:09: [irq 3]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:09: Plug and Play ACPI device, IDs PNP0501 (active)
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:0a: [io  0x0378-0x037f]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:0a: [io  0x0778-0x077b]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:0a: [irq 7]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:0a: Plug and Play ACPI device, IDs PNP0400 (active)
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:0b: [irq 12]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:0b: Plug and Play ACPI device, IDs PNP0f13 (active)
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:0c: [io  0x0060]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:0c: [io  0x0064]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:0c: [irq 1]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:0c: Plug and Play ACPI device, IDs PNP0303 PNP030b (active)
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:0d: [mem 0xe0000000-0xefffffff]
Jul 20 22:04:06 f6bvp-11 kernel: system 00:0d: [mem 0xe0000000-0xefffffff] has been reserved
Jul 20 22:04:06 f6bvp-11 kernel: system 00:0d: Plug and Play ACPI device, IDs PNP0c02 (active)
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:0e: [mem 0x000cec00-0x000cffff]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:0e: [mem 0x000f0000-0x000f7fff]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:0e: [mem 0x000f8000-0x000fbfff]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:0e: [mem 0x000fc000-0x000fffff]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:0e: [mem 0x7fee0000-0x7fefffff]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:0e: [mem 0xffff0000-0xffffffff]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:0e: [mem 0x00000000-0x0009ffff]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:0e: [mem 0x00100000-0x7fedffff]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:0e: [mem 0xfec00000-0xfec00fff]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:0e: [mem 0xfee00000-0xfee00fff]
Jul 20 22:04:06 f6bvp-11 kernel: pnp 00:0e: [mem 0xfff80000-0xfffeffff]
Jul 20 22:04:06 f6bvp-11 kernel: system 00:0e: [mem 0x000cec00-0x000cffff] has been reserved
Jul 20 22:04:06 f6bvp-11 kernel: system 00:0e: [mem 0x000f0000-0x000f7fff] could not be reserved
Jul 20 22:04:06 f6bvp-11 kernel: system 00:0e: [mem 0x000f8000-0x000fbfff] could not be reserved
Jul 20 22:04:06 f6bvp-11 kernel: system 00:0e: [mem 0x000fc000-0x000fffff] could not be reserved
Jul 20 22:04:06 f6bvp-11 kernel: system 00:0e: [mem 0x7fee0000-0x7fefffff] could not be reserved
Jul 20 22:04:06 f6bvp-11 kernel: system 00:0e: [mem 0xffff0000-0xffffffff] has been reserved
Jul 20 22:04:06 f6bvp-11 kernel: system 00:0e: [mem 0x00000000-0x0009ffff] could not be reserved
Jul 20 22:04:06 f6bvp-11 kernel: system 00:0e: [mem 0x00100000-0x7fedffff] could not be reserved
Jul 20 22:04:06 f6bvp-11 kernel: system 00:0e: [mem 0xfec00000-0xfec00fff] could not be reserved
Jul 20 22:04:06 f6bvp-11 kernel: system 00:0e: [mem 0xfee00000-0xfee00fff] has been reserved
Jul 20 22:04:06 f6bvp-11 kernel: system 00:0e: [mem 0xfff80000-0xfffeffff] has been reserved
Jul 20 22:04:06 f6bvp-11 kernel: system 00:0e: Plug and Play ACPI device, IDs PNP0c01 (active)
Jul 20 22:04:06 f6bvp-11 kernel: pnp: PnP ACPI: found 15 devices
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: ACPI bus type pnp unregistered
Jul 20 22:04:06 f6bvp-11 kernel: Switching to clocksource acpi_pm
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:01.0: PCI bridge to [bus 01-01]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:01.0:   bridge window [io  0x9000-0x9fff]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:01.0:   bridge window [mem 0xdfc00000-0xdfcfffff]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:01.0:   bridge window [mem 0xdfb00000-0xdfbfffff pref]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:02:00.0: BAR 6: assigned [mem 0xde000000-0xde01ffff pref]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:02.0: PCI bridge to [bus 02-02]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:02.0:   bridge window [io  0xb000-0xbfff]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:02.0:   bridge window [mem 0xdc000000-0xdeffffff]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:02.0:   bridge window [mem 0xc0000000-0xcfffffff 64bit pref]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:03.0: PCI bridge to [bus 03-03]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:03.0:   bridge window [io  0xa000-0xafff]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:03.0:   bridge window [mem 0xdfe00000-0xdfefffff]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:03.0:   bridge window [mem 0xdfd00000-0xdfdfffff 64bit pref]
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:01.0: setting latency timer to 64
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:02.0: PCI INT A -> GSI 27 (level, low) -> IRQ 27
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:02.0: setting latency timer to 64
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:03.0: PCI INT A -> GSI 31 (level, low) -> IRQ 31
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:03.0: setting latency timer to 64
Jul 20 22:04:06 f6bvp-11 kernel: pci_bus 0000:00: resource 4 [io  0x0000-0x0cf7]
Jul 20 22:04:06 f6bvp-11 kernel: pci_bus 0000:00: resource 5 [io  0x0d00-0xffff]
Jul 20 22:04:06 f6bvp-11 kernel: pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff]
Jul 20 22:04:06 f6bvp-11 kernel: pci_bus 0000:00: resource 7 [mem 0x000c0000-0x000dffff]
Jul 20 22:04:06 f6bvp-11 kernel: pci_bus 0000:00: resource 8 [mem 0x7ff00000-0xfebfffff]
Jul 20 22:04:06 f6bvp-11 kernel: pci_bus 0000:01: resource 0 [io  0x9000-0x9fff]
Jul 20 22:04:06 f6bvp-11 kernel: pci_bus 0000:01: resource 1 [mem 0xdfc00000-0xdfcfffff]
Jul 20 22:04:06 f6bvp-11 kernel: pci_bus 0000:01: resource 2 [mem 0xdfb00000-0xdfbfffff pref]
Jul 20 22:04:06 f6bvp-11 kernel: pci_bus 0000:02: resource 0 [io  0xb000-0xbfff]
Jul 20 22:04:06 f6bvp-11 kernel: pci_bus 0000:02: resource 1 [mem 0xdc000000-0xdeffffff]
Jul 20 22:04:06 f6bvp-11 kernel: pci_bus 0000:02: resource 2 [mem 0xc0000000-0xcfffffff 64bit pref]
Jul 20 22:04:06 f6bvp-11 kernel: pci_bus 0000:03: resource 0 [io  0xa000-0xafff]
Jul 20 22:04:06 f6bvp-11 kernel: pci_bus 0000:03: resource 1 [mem 0xdfe00000-0xdfefffff]
Jul 20 22:04:06 f6bvp-11 kernel: pci_bus 0000:03: resource 2 [mem 0xdfd00000-0xdfdfffff 64bit pref]
Jul 20 22:04:06 f6bvp-11 kernel: NET: Registered protocol family 2
Jul 20 22:04:06 f6bvp-11 kernel: IP route cache hash table entries: 65536 (order: 7, 524288 bytes)
Jul 20 22:04:06 f6bvp-11 kernel: TCP established hash table entries: 262144 (order: 10, 4194304 bytes)
Jul 20 22:04:06 f6bvp-11 kernel: Switched to NOHz mode on CPU #0
Jul 20 22:04:06 f6bvp-11 kernel: TCP bind hash table entries: 65536 (order: 8, 1048576 bytes)
Jul 20 22:04:06 f6bvp-11 kernel: TCP: Hash tables configured (established 262144 bind 65536)
Jul 20 22:04:06 f6bvp-11 kernel: TCP reno registered
Jul 20 22:04:06 f6bvp-11 kernel: UDP hash table entries: 1024 (order: 3, 32768 bytes)
Jul 20 22:04:06 f6bvp-11 kernel: UDP-Lite hash table entries: 1024 (order: 3, 32768 bytes)
Jul 20 22:04:06 f6bvp-11 kernel: NET: Registered protocol family 1
Jul 20 22:04:06 f6bvp-11 kernel: RPC: Registered udp transport module.
Jul 20 22:04:06 f6bvp-11 kernel: RPC: Registered tcp transport module.
Jul 20 22:04:06 f6bvp-11 kernel: RPC: Registered tcp NFSv4.1 backchannel transport module.
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:01.0: disabling DAC on VIA PCI bridge
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:00:11.0: Bypassing VIA 8237 APIC De-Assert Message
Jul 20 22:04:06 f6bvp-11 kernel: pci 0000:02:00.0: Boot video device
Jul 20 22:04:06 f6bvp-11 kernel: PCI: CLS 32 bytes, default 64
Jul 20 22:04:06 f6bvp-11 kernel: Trying to unpack rootfs image as initramfs...
Jul 20 22:04:06 f6bvp-11 kernel: Freeing initrd memory: 5360k freed
Jul 20 22:04:06 f6bvp-11 kernel: HugeTLB registered 2 MB page size, pre-allocated 0 pages
Jul 20 22:04:06 f6bvp-11 kernel: Installing knfsd (copyright (C) 1996 [email protected]).
Jul 20 22:04:06 f6bvp-11 kernel: msgmni has been set to 4021
Jul 20 22:04:06 f6bvp-11 kernel: Block layer SCSI generic (bsg) driver version 0.4 loaded (major 253)
Jul 20 22:04:06 f6bvp-11 kernel: io scheduler noop registered
Jul 20 22:04:06 f6bvp-11 kernel: io scheduler deadline registered
Jul 20 22:04:06 f6bvp-11 kernel: io scheduler cfq registered (default)
Jul 20 22:04:06 f6bvp-11 kernel: pcieport 0000:00:02.0: setting latency timer to 64
Jul 20 22:04:06 f6bvp-11 kernel: pcieport 0000:00:02.0: irq 64 for MSI/MSI-X
Jul 20 22:04:06 f6bvp-11 kernel: pcieport 0000:00:03.0: setting latency timer to 64
Jul 20 22:04:06 f6bvp-11 kernel: pcieport 0000:00:03.0: irq 65 for MSI/MSI-X
Jul 20 22:04:06 f6bvp-11 kernel: vesafb: mode is 800x600x16, linelength=1600, pages=2
Jul 20 22:04:06 f6bvp-11 kernel: vesafb: scrolling: redraw
Jul 20 22:04:06 f6bvp-11 kernel: vesafb: Truecolor: size=0:5:6:5, shift=0:11:5:0
Jul 20 22:04:06 f6bvp-11 kernel: vesafb: framebuffer at 0xc0000000, mapped to 0xffffc90010980000, using 1875k, total 262144k
Jul 20 22:04:06 f6bvp-11 kernel: Console: switching to colour frame buffer device 100x37
Jul 20 22:04:06 f6bvp-11 kernel: fb0: VESA VGA frame buffer device
Jul 20 22:04:06 f6bvp-11 kernel: Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
Jul 20 22:04:06 f6bvp-11 kernel: serial8250: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
Jul 20 22:04:06 f6bvp-11 kernel: serial8250: ttyS1 at I/O 0x2f8 (irq = 3) is a 16550A
Jul 20 22:04:06 f6bvp-11 kernel: 00:08: ttyS0 at I/O 0x3f8 (irq = 4) is a 16550A
Jul 20 22:04:06 f6bvp-11 kernel: 00:09: ttyS1 at I/O 0x2f8 (irq = 3) is a 16550A
Jul 20 22:04:06 f6bvp-11 kernel: Linux agpgart interface v0.103
Jul 20 22:04:06 f6bvp-11 kernel: brd: module loaded
Jul 20 22:04:06 f6bvp-11 kernel: Uniform Multi-Platform E-IDE driver
Jul 20 22:04:06 f6bvp-11 kernel: i8042: PNP: PS/2 Controller [PNP0303:PS2K,PNP0f13:PS2M] at 0x60,0x64 irq 1,12
Jul 20 22:04:06 f6bvp-11 kernel: serio: i8042 KBD port at 0x60,0x64 irq 1
Jul 20 22:04:06 f6bvp-11 kernel: serio: i8042 AUX port at 0x60,0x64 irq 12
Jul 20 22:04:06 f6bvp-11 kernel: mousedev: PS/2 mouse device common for all mice
Jul 20 22:04:06 f6bvp-11 kernel: cpuidle: using governor ladder
Jul 20 22:04:06 f6bvp-11 kernel: cpuidle: using governor menu
Jul 20 22:04:06 f6bvp-11 kernel: TCP cubic registered
Jul 20 22:04:06 f6bvp-11 kernel: Registering the dns_resolver key type
Jul 20 22:04:06 f6bvp-11 kernel: input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input0
Jul 20 22:04:06 f6bvp-11 kernel: Refined TSC clocksource calibration: 2194.500 MHz.
Jul 20 22:04:06 f6bvp-11 kernel: Switching to clocksource tsc
Jul 20 22:04:06 f6bvp-11 kernel: input: ImExPS/2 Logitech Wheel Mouse as /devices/platform/i8042/serio1/input/input1
Jul 20 22:04:06 f6bvp-11 kernel: registered taskstats version 1
Jul 20 22:04:06 f6bvp-11 kernel: Freeing unused kernel memory: 632k freed
Jul 20 22:04:06 f6bvp-11 kernel: SCSI subsystem initialized
Jul 20 22:04:06 f6bvp-11 kernel: libata version 3.00 loaded.
Jul 20 22:04:06 f6bvp-11 kernel: sata_via 0000:00:0f.0: version 2.6
Jul 20 22:04:06 f6bvp-11 kernel: sata_via 0000:00:0f.0: PCI INT B -> Link[ALKA] -> GSI 20 (level, low) -> IRQ 20
Jul 20 22:04:06 f6bvp-11 kernel: sata_via 0000:00:0f.0: routed to hard irq line 11
Jul 20 22:04:06 f6bvp-11 kernel: scsi0 : sata_via
Jul 20 22:04:06 f6bvp-11 kernel: scsi1 : sata_via
Jul 20 22:04:06 f6bvp-11 kernel: ata1: SATA max UDMA/133 cmd 0xf800 ctl 0xf400 bmdma 0xe800 irq 20
Jul 20 22:04:06 f6bvp-11 kernel: ata2: SATA max UDMA/133 cmd 0xf000 ctl 0xec00 bmdma 0xe808 irq 20
Jul 20 22:04:06 f6bvp-11 kernel: ata1: SATA link down 1.5 Gbps (SStatus 0 SControl 300)
Jul 20 22:04:06 f6bvp-11 kernel: ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
Jul 20 22:04:06 f6bvp-11 kernel: ata2.00: ATA-7: Hitachi HDT725032VLA360, V54OA7EA, max UDMA/133
Jul 20 22:04:06 f6bvp-11 kernel: ata2.00: 625142448 sectors, multi 16: LBA48 NCQ (depth 0/32)
Jul 20 22:04:06 f6bvp-11 kernel: ata2.00: configured for UDMA/133
Jul 20 22:04:06 f6bvp-11 kernel: scsi 1:0:0:0: Direct-Access     ATA      Hitachi HDT72503 V54O PQ: 0 ANSI: 5
Jul 20 22:04:06 f6bvp-11 kernel: sd 1:0:0:0: [sda] 625142448 512-byte logical blocks: (320 GB/298 GiB)
Jul 20 22:04:06 f6bvp-11 kernel: sd 1:0:0:0: [sda] Write Protect is off
Jul 20 22:04:06 f6bvp-11 kernel: sd 1:0:0:0: [sda] Mode Sense: 00 3a 00 00
Jul 20 22:04:06 f6bvp-11 kernel: sd 1:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Jul 20 22:04:06 f6bvp-11 kernel: sda: sda1 sda2 < sda5 sda6 >
Jul 20 22:04:06 f6bvp-11 kernel: sd 1:0:0:0: [sda] Attached SCSI disk
Jul 20 22:04:06 f6bvp-11 kernel: pata_acpi 0000:00:0f.1: PCI INT A -> Link[ALKA] -> GSI 20 (level, low) -> IRQ 20
Jul 20 22:04:06 f6bvp-11 kernel: pata_acpi 0000:00:0f.1: PCI INT A disabled
Jul 20 22:04:06 f6bvp-11 kernel: pata_via 0000:00:0f.1: version 0.3.4
Jul 20 22:04:06 f6bvp-11 kernel: pata_via 0000:00:0f.1: PCI INT A -> Link[ALKA] -> GSI 20 (level, low) -> IRQ 20
Jul 20 22:04:06 f6bvp-11 kernel: scsi2 : pata_via
Jul 20 22:04:06 f6bvp-11 kernel: scsi3 : pata_via
Jul 20 22:04:06 f6bvp-11 kernel: ata3: PATA max UDMA/133 cmd 0x1f0 ctl 0x3f6 bmdma 0xe000 irq 14
Jul 20 22:04:06 f6bvp-11 kernel: ata4: PATA max UDMA/133 cmd 0x170 ctl 0x376 bmdma 0xe008 irq 15
Jul 20 22:04:06 f6bvp-11 kernel: ata3.00: ATAPI: TSSTcorpCD/DVDW TS-H552B, TS05, max UDMA/33
Jul 20 22:04:06 f6bvp-11 kernel: ata3.00: configured for UDMA/33
Jul 20 22:04:06 f6bvp-11 kernel: scsi 2:0:0:0: CD-ROM            TSSTcorp CD/DVDW TS-H552B TS05 PQ: 0 ANSI: 5
Jul 20 22:04:06 f6bvp-11 kernel: ata4.00: ATA-6: ST3120026A, 3.06, max UDMA/100
Jul 20 22:04:06 f6bvp-11 kernel: ata4.00: 234441648 sectors, multi 16: LBA48 
Jul 20 22:04:06 f6bvp-11 kernel: ata4.00: configured for UDMA/33
Jul 20 22:04:06 f6bvp-11 kernel: scsi 3:0:0:0: Direct-Access     ATA      ST3120026A       3.06 PQ: 0 ANSI: 5
Jul 20 22:04:06 f6bvp-11 kernel: sd 3:0:0:0: [sdb] 234441648 512-byte logical blocks: (120 GB/111 GiB)
Jul 20 22:04:06 f6bvp-11 kernel: sd 3:0:0:0: [sdb] Write Protect is off
Jul 20 22:04:06 f6bvp-11 kernel: sd 3:0:0:0: [sdb] Mode Sense: 00 3a 00 00
Jul 20 22:04:06 f6bvp-11 kernel: sd 3:0:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Jul 20 22:04:06 f6bvp-11 kernel: sdb: sdb1 sdb2 < sdb5 >
Jul 20 22:04:06 f6bvp-11 kernel: sd 3:0:0:0: [sdb] Attached SCSI disk
Jul 20 22:04:06 f6bvp-11 kernel: EXT4-fs (sda1): mounted filesystem with ordered data mode. Opts: acl
Jul 20 22:04:06 f6bvp-11 kernel: udev: starting version 153
Jul 20 22:04:06 f6bvp-11 kernel: agpgart: Detected VIA P4M890 chipset
Jul 20 22:04:06 f6bvp-11 kernel: agpgart-via 0000:00:00.0: AGP aperture is 128M @ 0xd0000000
Jul 20 22:04:06 f6bvp-11 kernel: input: Power Button as /devices/LNXSYSTM:00/device:00/PNP0C0C:00/input/input2
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: Power Button [PWRB]
Jul 20 22:04:06 f6bvp-11 kernel: input: Sleep Button as /devices/LNXSYSTM:00/device:00/PNP0C0E:00/input/input3
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: Sleep Button [SLPB]
Jul 20 22:04:06 f6bvp-11 kernel: input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input4
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: Power Button [PWRF]
Jul 20 22:04:06 f6bvp-11 kernel: rtc_cmos 00:04: RTC can wake from S4
Jul 20 22:04:06 f6bvp-11 kernel: rtc_cmos 00:04: rtc core: registered rtc_cmos as rtc0
Jul 20 22:04:06 f6bvp-11 kernel: rtc0: alarms up to one year, y3k, 242 bytes nvram
Jul 20 22:04:06 f6bvp-11 kernel: FDC 0 is a post-1991 82077
Jul 20 22:04:06 f6bvp-11 kernel: ACPI: acpi_idle registered with cpuidle
Jul 20 22:04:06 f6bvp-11 kernel: EXT4-fs (sda1): re-mounted. Opts: acl
Jul 20 22:04:06 f6bvp-11 kernel: EXT4-fs (sda6): mounted filesystem with ordered data mode. Opts: acl
Jul 20 22:04:06 f6bvp-11 kernel: EXT4-fs (sdb5): mounted filesystem with ordered data mode. Opts: (null)
Jul 20 22:04:06 f6bvp-11 kernel: Adding 4088504k swap on /dev/sda5.  Priority:-1 extents:1 across:4088504k 
Jul 20 22:04:07 f6bvp-11 kernel: [drm] Initialized drm 1.1.0 20060810
Jul 20 22:04:07 f6bvp-11 kernel: nouveau 0000:02:00.0: PCI INT A -> GSI 24 (level, low) -> IRQ 24
Jul 20 22:04:07 f6bvp-11 kernel: nouveau 0000:02:00.0: setting latency timer to 64
Jul 20 22:04:07 f6bvp-11 kernel: [drm] nouveau 0000:02:00.0: Detected an NV40 generation card (0x04b200a2)
Jul 20 22:04:07 f6bvp-11 kernel: checking generic (c0000000 10000000) vs hw (c0000000 10000000)
Jul 20 22:04:07 f6bvp-11 kernel: fb: conflicting fb hw usage nouveaufb vs VESA VGA - removing generic driver
Jul 20 22:04:07 f6bvp-11 kernel: Console: switching to colour dummy device 80x25
Jul 20 22:04:07 f6bvp-11 kernel: [drm] nouveau 0000:02:00.0: Attempting to load BIOS image from PRAMIN
Jul 20 22:04:07 f6bvp-11 kernel: [drm] nouveau 0000:02:00.0: ... appears to be valid
Jul 20 22:04:07 f6bvp-11 kernel: [drm] nouveau 0000:02:00.0: BIT BIOS found
Jul 20 22:04:07 f6bvp-11 kernel: [drm] nouveau 0000:02:00.0: Bios version 05.73.22.19
Jul 20 22:04:07 f6bvp-11 kernel: [drm] nouveau 0000:02:00.0: TMDS table version 1.1
Jul 20 22:04:07 f6bvp-11 kernel: [drm] nouveau 0000:02:00.0: BIT table 'd' not found
Jul 20 22:04:07 f6bvp-11 kernel: [drm] nouveau 0000:02:00.0: Found Display Configuration Block version 3.0
Jul 20 22:04:07 f6bvp-11 kernel: [drm] nouveau 0000:02:00.0: Raw DCB entry 0: 01000300 00000028
Jul 20 22:04:07 f6bvp-11 kernel: [drm] nouveau 0000:02:00.0: Raw DCB entry 1: 03011312 00000000
Jul 20 22:04:07 f6bvp-11 kernel: [drm] nouveau 0000:02:00.0: Raw DCB entry 2: 04011310 00000028
Jul 20 22:04:07 f6bvp-11 kernel: [drm] nouveau 0000:02:00.0: Raw DCB entry 3: 020223f1 00c0c080
Jul 20 22:04:07 f6bvp-11 kernel: [drm] nouveau 0000:02:00.0: DCB connector table: VHER 0x30 5 10 2
Jul 20 22:04:07 f6bvp-11 kernel: [drm] nouveau 0000:02:00.0:   0: 0x00001030: type 0x30 idx 0 tag 0x07
Jul 20 22:04:07 f6bvp-11 kernel: [drm] nouveau 0000:02:00.0:   1: 0x00000100: type 0x00 idx 1 tag 0xff
Jul 20 22:04:07 f6bvp-11 kernel: [drm] nouveau 0000:02:00.0:   2: 0x00000210: type 0x10 idx 2 tag 0xff
Jul 20 22:04:07 f6bvp-11 kernel: [drm] nouveau 0000:02:00.0:   3: 0x00000211: type 0x11 idx 3 tag 0xff
Jul 20 22:04:07 f6bvp-11 kernel: [drm] nouveau 0000:02:00.0:   4: 0x00000213: type 0x13 idx 4 tag 0xff
Jul 20 22:04:07 f6bvp-11 kernel: [drm] nouveau 0000:02:00.0: Parsing VBIOS init table 0 at offset 0xDDCC
Jul 20 22:04:07 f6bvp-11 kernel: [drm] nouveau 0000:02:00.0: Parsing VBIOS init table 1 at offset 0xE446
Jul 20 22:04:07 f6bvp-11 kernel: [drm] nouveau 0000:02:00.0: Parsing VBIOS init table 2 at offset 0xEB09
Jul 20 22:04:07 f6bvp-11 kernel: [drm] nouveau 0000:02:00.0: Parsing VBIOS init table 3 at offset 0xEC84
Jul 20 22:04:07 f6bvp-11 kernel: [drm] nouveau 0000:02:00.0: Parsing VBIOS init table 4 at offset 0xEE72
Jul 20 22:04:08 f6bvp-11 kernel: [drm] nouveau 0000:02:00.0: 1 available performance level(s)
Jul 20 22:04:08 f6bvp-11 kernel: [drm] nouveau 0000:02:00.0: 0: memory 400MHz core 400MHz voltage 1100mV fanspeed 100%
Jul 20 22:04:08 f6bvp-11 kernel: [drm] nouveau 0000:02:00.0: c: memory 405MHz core 400MHz
Jul 20 22:04:08 f6bvp-11 kernel: nouveau 0000:02:00.0: PCI: Disallowing DAC for device
Jul 20 22:04:08 f6bvp-11 kernel: [TTM] Zone  kernel: Available graphics memory: 1029758 kiB.
Jul 20 22:04:08 f6bvp-11 kernel: [TTM] Initializing pool allocator.
Jul 20 22:04:08 f6bvp-11 kernel: [drm] nouveau 0000:02:00.0: Detected 256MiB VRAM
Jul 20 22:04:08 f6bvp-11 kernel: [drm] nouveau 0000:02:00.0: 512 MiB GART (aperture)
Jul 20 22:04:08 f6bvp-11 kernel: [drm] Supports vblank timestamp caching Rev 1 (10.10.2010).
Jul 20 22:04:08 f6bvp-11 kernel: [drm] No driver support for vblank timestamp query.
Jul 20 22:04:08 f6bvp-11 kernel: [drm] nouveau 0000:02:00.0: Setting dpms mode 3 on vga encoder (output 0)
Jul 20 22:04:08 f6bvp-11 kernel: [drm] nouveau 0000:02:00.0: Setting dpms mode 3 on tmds encoder (output 1)
Jul 20 22:04:08 f6bvp-11 kernel: [drm] nouveau 0000:02:00.0: Setting dpms mode 3 on vga encoder (output 2)
Jul 20 22:04:08 f6bvp-11 kernel: [drm] nouveau 0000:02:00.0: Setting dpms mode 3 on TV encoder (output 3)
Jul 20 22:04:08 f6bvp-11 kernel: [drm] nouveau 0000:02:00.0: allocated 1280x1024 fb: 0x49000, bo ffff88007c039000
Jul 20 22:04:08 f6bvp-11 kernel: fbcon: nouveaufb (fb0) is primary device
Jul 20 22:04:08 f6bvp-11 kernel: Console: switching to colour frame buffer device 160x64
Jul 20 22:04:08 f6bvp-11 kernel: fb0: nouveaufb frame buffer device
Jul 20 22:04:08 f6bvp-11 kernel: drm: registered panic notifier
Jul 20 22:04:08 f6bvp-11 kernel: [drm] Initialized nouveau 0.0.16 20090420 for 0000:02:00.0 on minor 0
Jul 20 22:04:08 f6bvp-11 kernel: [drm] nouveau 0000:02:00.0: Setting dpms mode 0 on vga encoder (output 0)
Jul 20 22:04:08 f6bvp-11 kernel: [drm] nouveau 0000:02:00.0: Output VGA-1 is running on CRTC 0 using output A
Jul 20 22:04:17 f6bvp-11 kernel: cdrom: Uniform CD-ROM driver Revision: 3.20
Jul 20 22:04:17 f6bvp-11 kernel: sr 2:0:0:0: Attached scsi CD-ROM sr0
Jul 20 22:04:17 f6bvp-11 kernel: sd 1:0:0:0: Attached scsi generic sg0 type 0
Jul 20 22:04:17 f6bvp-11 kernel: sr 2:0:0:0: Attached scsi generic sg1 type 5
Jul 20 22:04:17 f6bvp-11 kernel: sd 3:0:0:0: Attached scsi generic sg2 type 0
Jul 20 22:04:17 f6bvp-11 kernel: 8139too: 8139too Fast Ethernet driver 0.9.28
Jul 20 22:04:17 f6bvp-11 kernel: 8139too 0000:00:0b.0: PCI INT A -> GSI 21 (level, low) -> IRQ 21
Jul 20 22:04:17 f6bvp-11 kernel: 8139too 0000:00:0b.0: eth0: RealTek RTL8139 at 0xffffc90012c5c000, 00:16:17:b3:e9:6c, IRQ 21
Jul 20 22:04:17 f6bvp-11 kernel: 8139cp: 8139cp: 10/100 PCI Ethernet driver v1.3 (Mar 22, 2004)
Jul 20 22:04:18 f6bvp-11 kernel: VIA 82xx Audio 0000:00:11.5: PCI INT C -> Link[ALKC] -> GSI 22 (level, low) -> IRQ 22
Jul 20 22:04:18 f6bvp-11 kernel: VIA 82xx Audio 0000:00:11.5: setting latency timer to 64
Jul 20 22:04:19 f6bvp-11 kernel: NET: Registered protocol family 10
Jul 20 22:04:20 f6bvp-11 kernel: 8139too 0000:00:0b.0: eth0: link up, 100Mbps, full-duplex, lpa 0x45E1
Jul 20 22:04:20 f6bvp-11 kernel: NET: Registered protocol family 17
Jul 20 22:04:47 f6bvp-11 kernel: NET: Registered protocol family 3
Jul 20 22:04:47 f6bvp-11 kernel: mkiss: AX.25 Multikiss, Hans Albas PE1AYX
Jul 20 22:04:47 f6bvp-11 kernel: mkiss: ax0: crc mode is auto.
Jul 20 22:04:47 f6bvp-11 kernel: ADDRCONF(NETDEV_CHANGE): ax0: link becomes ready
Jul 20 22:04:51 f6bvp-11 kernel: mkiss: ax1: crc mode is auto.
Jul 20 22:04:51 f6bvp-11 kernel: ADDRCONF(NETDEV_CHANGE): ax1: link becomes ready
Jul 20 22:04:51 f6bvp-11 kernel: mkiss: ax2: crc mode is auto.
Jul 20 22:04:51 f6bvp-11 kernel: ADDRCONF(NETDEV_CHANGE): ax2: link becomes ready
Jul 20 22:04:59 f6bvp-11 kernel: NET: Registered protocol family 11
Jul 20 22:04:59 f6bvp-11 kernel: ROSE: socket is bound
Jul 20 22:04:59 f6bvp-11 kernel: mkiss: ax0: Trying crc-smack
Jul 20 22:05:02 f6bvp-11 kernel: mkiss: ax0: Trying crc-flexnet
Jul 20 22:05:02 f6bvp-11 kernel: mkiss: ax2: Trying crc-smack
Jul 20 22:05:05 f6bvp-11 kernel: mkiss: ax2: Trying crc-flexnet
Jul 20 22:05:13 f6bvp-11 kernel: netconsole: local port 6666
Jul 20 22:05:13 f6bvp-11 kernel: netconsole: local IP 192.168.0.68
Jul 20 22:05:13 f6bvp-11 kernel: netconsole: interface 'eth0'
Jul 20 22:05:13 f6bvp-11 kernel: netconsole: remote port 4444
Jul 20 22:05:13 f6bvp-11 kernel: netconsole: remote IP 192.168.0.64
Jul 20 22:05:13 f6bvp-11 kernel: netconsole: remote ethernet address 00:21:85:5e:a8:9e
Jul 20 22:05:13 f6bvp-11 kernel: console [netcon0] enabled
Jul 20 22:05:13 f6bvp-11 kernel: netconsole: network logging started
Jul 20 22:07:40 f6bvp-11 kernel: AX.25: sendto: Addresses built. Building packet.
Jul 20 22:07:40 f6bvp-11 kernel: AX.25: Appending user data
Jul 20 22:07:40 f6bvp-11 kernel: AX.25: Transmitting buffer
Jul 20 22:07:41 f6bvp-11 kernel: AX.25: sendto: Addresses built. Building packet.
Jul 20 22:07:41 f6bvp-11 kernel: AX.25: Appending user data
Jul 20 22:07:41 f6bvp-11 kernel: AX.25: Transmitting buffer

SMP has become the norm - I think in the x86 world something like an Atom netbook is one of the few remaining options to buy a single core system.

This is only an optimization to make the scheduler more effective on systems that have hyperthreaded hardware. Aside enabling or not enabling this option should not have any impact on system behaviour.

The reason I'm asking is that hyperthreading and multi-core fall into the SMP cathegorie for the OS, that is the present the same sort of challenges to the networking stack. Of course all the issues are only going to strike if multiple processors are active. In other words, it's SMP if /proc/cpuinfo shows the presence of multiple processors.

And preemptable kernels pose like 95% of the same issues as SMP does.

Ralf

My two ROSE-FPAC nodes have been running for 8 days and 12 hours without disruption.

Tonight I noticed that "use" parameter was negative (-1) while remote node station F8COJ-11 was not connected (restart = "no" and tf counting).

Later, F8COJ-11 node got connected again (restart = "yes") and "use" = 1. Then "use" returned to 0 after a few minutes.

This system is the one with SMP kernel and Voluntary Kernel Preemption (Desktop).

/proc/net/rose_neigh

addr callsign dev count use mode restart t0 tf digipeaters

00005 F6BVP-5 ax2 1 0 DTE no 0 99

00004 F8COJ-11 ax2 2 -1 DTE no 0 87

00003 F6BVP-11 ax1 11 0 DTE no 0 0

00002 K4GBB-12 ax2 9 0 DCE yes 0 0

00001 RSLOOP-0 ??? 1 2 DCE yes 0 0

/proc/net/rose_neigh

addr callsign dev count use mode restart t0 tf digipeaters

00005 F6BVP-5 ax2 1 0 DTE no 0 0

00004 F8COJ-11 ax2 2 1 DCE yes 0 0

00003 F6BVP-11 ax1 11 0 DTE no 0 0

00002 K4GBB-12 ax2 9 0 DCE yes 0 0

00001 RSLOOP-0 ??? 1 2 DCE yes 0 0

/proc/net/rose_neigh

addr callsign dev count use mode restart t0 tf digipeaters

00005 F6BVP-5 ax2 1 0 DTE no 0 0

00004 F8COJ-11 ax2 2 0 DCE yes 0 0

00003 F6BVP-11 ax1 11 0 DTE no 0 0

00002 K4GBB-12 ax2 9 0 DCE yes 0 0

00001 RSLOOP-0 ??? 1 2 DCE yes 0 0

At the same times, on my second Linux system (with maxcpus=1 boot kernel parameter),
use was 0 when not connected and it keeps displaying use=1 since ROSE neighbour F8COJ has been connected again.

However, both nodes are performing well and are able to route ROSE frames to F8COJ-11.

Bernard

--
To unsubscribe from this list: send the line "unsubscribe linux-hams" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

Hello Ralf,

Since my last post my two ROSE/FPAC nodes have been running flawlessly with last ROSE patches for nearly 17 days. Situation remains the same, i.e. from time to time use can still be negative.

Here is a /proc/net/rose/neigh dump from the machine running dual core CPU with SMP kernel :

/proc/net/rose_neigh

addr  callsign  dev  count use mode restart  t0  tf digipeaters
00005 F6BVP-5   ax2      1   0  DTE      no   0   0
00004 F8COJ-11  ax2      2  -1  DTE      yes   0   0
00003 F6BVP-11  ax1     11   0  DTE      no   0   0
00002 K4GBB-12  ax2      9   0  DCE     yes   0   0
00001 RSLOOP-0  ???      1   2  DCE     yes   0   0

For the present time "use" parameter has returned to 0 for F8COJ-11 node neighbor on the other system without manual change.
Thus I guess some situations can reinitialize "use" counter.
I will then investigate if use can also become negative on this second system if I do not switch to UMP mode at boot (removing maxcpus=1 boot option).

/proc/net/rose_neigh

addr  callsign  dev  count use mode restart  t0  tf digipeaters
00020 F6BVP-5   ax0      1   0  DTE      no   0   0
00019 F6BVP-7   ax0      2   0  DTE      no   0   0
00018 F6BVP-9   ax2      2   0  DTE      no   0   0
00017 F3KT-11   ax0      3   0  DCE     yes   0   0
00016 F8COJ-11  ax0      2   0  DCE     yes   0   0
00015 F6GGY-9   ax0      3   0  DTE      no   0   0
....
00002 TI2HAS-9  ax0      5   0  DTE      no   0   0
00001 RSLOOP-0  ???      1   0  DCE     yes   0   0

Bernard

--
To unsubscribe from this list: send the line "unsubscribe linux-hams" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

This at least means there should be no regressions by my patch series and it's getting time to send it upstream in a few days when I sorted out my b0rked DSL line and new workstation. With these holes plugged finding what's actually causing the use counters to go negative should also have gotten a little easier.

Thanks,

Ralf

Hello Ralf,

Booting 3.0.1 kernel with ROSE patches in SMP mode gives systematically the following Inconsistent Lock State.
See attached file.

Bernard

=================================
[ INFO: inconsistent lock state ]
3.0.1 #1
---------------------------------
inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
kworker/0:1/11 [HC0[0]:SC1[5]:HE1:SE0] takes:
(rose_callsign_lock){+.?...}, at: [<ffffffffa05d2128>] rose_get_neigh_callsign+0x28/0x80 [rose]
{SOFTIRQ-ON-W} state was registered at:

  [<ffffffff81096ed4>] __lock_acquire+0x5f4/0x1620
  [<ffffffff810984f2>] lock_acquire+0xa2/0x120
  [<ffffffff813fece1>] _raw_spin_lock+0x31/0x40
  [<ffffffffa021d068>] 0xffffffffa021d068
  [<ffffffff81002043>] do_one_initcall+0x43/0x190
  [<ffffffff810a4630>] sys_init_module+0x90/0x1f0
  [<ffffffff81407652>] system_call_fastpath+0x16/0x1b
irq event stamp: 17758
hardirqs last  enabled at (17758): [<ffffffff813ff4e0>] _raw_spin_unlock_irqrestore+0x40/0x70
hardirqs last disabled at (17757): [<ffffffff813fedde>] _raw_spin_lock_irqsave+0x2e/0x70
softirqs last  enabled at (17720): [<ffffffffa0184532>] mkiss_receive_buf+0x2e2/0x3dc [mkiss]
softirqs last disabled at (17721): [<ffffffff814088dc>] call_softirq+0x1c/0x30

other info that might help us debug this:

 Possible unsafe locking scenario:

       CPU0
       ----
  lock(rose_callsign_lock);
  <Interrupt>
    lock(rose_callsign_lock);

*** DEADLOCK ***

5 locks held by kworker/0:1/11:

 #0:  (events){.+.+.+}, at: [<ffffffff810772c7>] process_one_work+0x137/0x520
 #1:  ((&tty->buf.work)){+.+...}, at: [<ffffffff810772c7>] process_one_work+0x137/0x520
 #2:  (rcu_read_lock){.+.+..}, at: [<ffffffff81340c2b>] __netif_receive_skb+0xeb/0x6a0
 #3:  (rose_neigh_list_lock){+.-...}, at: [<ffffffffa05d3c29>] rose_route_frame+0x79/0x6c0 [rose]
 #4:  (rose_route_list_lock){+.-...}, at: [<ffffffffa05d3c35>] rose_route_frame+0x85/0x6c0 [rose]

stack backtrace:
Pid: 11, comm: kworker/0:1 Not tainted 3.0.1 #1
Call Trace:
 <IRQ>  [<ffffffff810953b5>] print_usage_bug+0x225/0x270
 [<ffffffff810961a3>] mark_lock+0x323/0x3f0
 [<ffffffff81096e5e>] __lock_acquire+0x57e/0x1620
 [<ffffffff810973f3>] ? __lock_acquire+0xb13/0x1620
 [<ffffffff810984f2>] lock_acquire+0xa2/0x120
 [<ffffffffa05d2128>] ? rose_get_neigh_callsign+0x28/0x80 [rose]
 [<ffffffff813fece1>] _raw_spin_lock+0x31/0x40
 [<ffffffffa05d2128>] ? rose_get_neigh_callsign+0x28/0x80 [rose]
 [<ffffffff81096505>] ? trace_hardirqs_on_caller+0x65/0x180
 [<ffffffffa05d2128>] rose_get_neigh_callsign+0x28/0x80 [rose]
 [<ffffffffa05d22d3>] rose_send_frame+0x33/0xb0 [rose]
 [<ffffffff81333956>] ? skb_dequeue+0x66/0x90
 [<ffffffffa05d266b>] rose_link_rx_restart+0x6b/0x170 [rose]
 [<ffffffffa05d3d21>] rose_route_frame+0x171/0x6c0 [rose]
 [<ffffffff8106ab6c>] ? lock_timer_base+0x3c/0x70
 [<ffffffffa05bf96c>] ? ax25_protocol_function+0x1c/0x70 [ax25]
 [<ffffffff813ff4e0>] ? _raw_spin_unlock_irqrestore+0x40/0x70
 [<ffffffffa05d3bb0>] ? rose_get_neigh+0x1a0/0x1a0 [rose]
 [<ffffffffa05c08f7>] ax25_rx_iframe+0x77/0x350 [ax25]
 [<ffffffffa05c2f6e>] ax25_std_frame_in+0x8be/0x920 [ax25]
 [<ffffffffa05c641c>] ? ax25_find_cb+0xcc/0x120 [ax25]
 [<ffffffffa05c01da>] ax25_rcv+0x3aa/0x9a0 [ax25]
 [<ffffffff810962db>] ? mark_held_locks+0x6b/0xa0
 [<ffffffff813ff4e0>] ? _raw_spin_unlock_irqrestore+0x40/0x70
 [<ffffffff8132f69a>] ? sock_def_readable+0x8a/0xb0
 [<ffffffff8132f610>] ? sock_get_timestamp+0xc0/0xc0
 [<ffffffffa05c086f>] ax25_kiss_rcv+0x9f/0xb0 [ax25]
 [<ffffffff81340d4d>] __netif_receive_skb+0x20d/0x6a0
 [<ffffffff81340c2b>] ? __netif_receive_skb+0xeb/0x6a0
 [<ffffffff813412b4>] process_backlog+0xd4/0x1e0
 [<ffffffff81342e55>] net_rx_action+0x125/0x280
 [<ffffffff81062196>] __do_softirq+0xc6/0x210
 [<ffffffff814088dc>] call_softirq+0x1c/0x30
 <EOI>  [<ffffffff8100d43d>] ? do_softirq+0x9d/0xd0
 [<ffffffffa0184532>] ? mkiss_receive_buf+0x2e2/0x3dc [mkiss]
 [<ffffffff81062efb>] local_bh_enable_ip+0xeb/0xf0
 [<ffffffff813ff454>] _raw_spin_unlock_bh+0x34/0x40
 [<ffffffffa0184532>] mkiss_receive_buf+0x2e2/0x3dc [mkiss]
 [<ffffffff812a5f4a>] flush_to_ldisc+0x18a/0x1a0
 [<ffffffff81077336>] process_one_work+0x1a6/0x520
 [<ffffffff810772c7>] ? process_one_work+0x137/0x520
 [<ffffffff812a5dc0>] ? tty_schedule_flip+0x60/0x60
 [<ffffffff81079ca3>] worker_thread+0x173/0x400
 [<ffffffff81079b30>] ? manage_workers+0x210/0x210
 [<ffffffff8107e886>] kthread+0xb6/0xc0
 [<ffffffff810965dd>] ? trace_hardirqs_on_caller+0x13d/0x180
 [<ffffffff814087e4>] kernel_thread_helper+0x4/0x10
 [<ffffffff813ff894>] ? retint_restore_args+0x13/0x13
 [<ffffffff8107e7d0>] ? __init_kthread_worker+0x70/0x70
 [<ffffffff814087e0>] ? gs_change+0x13/0x13

mkiss: ax1: Trying crc-flexnet
mkiss: ax0: Trying crc-smack
type=1305 audit(1312815573.499:96604): auid=4294967295 ses=4294967295 op="remove rule" key=(null) list=4 res=1 type=1305 audit(1312815573.499:96605): audit_enabled=0 old=1 auid=4294967295 ses=4294967295 res=1
mkiss: ax0: Trying crc-flexnet
[root@f6bvp-8 bernard]#

Hello Ralf,

Running kernel 3.0.3 with rose patches.
Looking at the following code it seems that first spin_unlock is misplaced just before memcpy().

I tried to move spin_unlock just after the call to memcpy without change. The DEADLOCK is still there.

static void rose_get_neigh_callsign(ax25_address *rose_call,
struct rose_neigh *neigh)

{
        spin_lock(&rose_callsign_lock);
        if (ax25cmp(&rose_callsign, &null_ax25_address) == 0) {
                spin_unlock(&rose_callsign_lock);
                memcpy(rose_call, neigh->dev->dev_addr, sizeof(rose_call));

                return;
        }

When examining the inconsistent lock state report I may understand the reason. The sequence is :

rose_route_frame()
rose_link_rx_start()
rose_send_frame()
rose_get_neigh_callsign()

However, rose_route_frame() is locking rose_route_list and rose_route_neigh_list with spin_lock_bh and if lci==0 there is a call in the function to rose_link_rx_restart before unlocking the lists. If (neigh->restarted) rose_send_frame() is called and in turn will call rose_get_neigh_callsign() that tries to spin_lock rose_callsign_lock and here comes the conflicting situation.

Thus I modified rose_route_frame() in order to spin_unlock both lists before calling rose_link_rx_start().

Here are my patches.

However, another inconsistent lock state remains as you will see in the following attached file.

73 de Bernard

@@ -99,8 +99,8 @@ static void rose_get_neigh_callsign(ax25
 {
 	spin_lock(&rose_callsign_lock);
 	if (ax25cmp(&rose_callsign, &null_ax25_address) == 0) {
-		spin_unlock(&rose_callsign_lock);
 		memcpy(rose_call, neigh->dev->dev_addr, sizeof(rose_call));
+		spin_unlock(&rose_callsign_lock);
 
 		return;
 	}

@@ -910,8 +910,10 @@ int rose_route_frame(struct sk_buff *skb
 	 * 	frame.
 	 */
 	if (lci == 0) {
+		spin_unlock_bh(&rose_neigh_list_lock);
+		spin_unlock_bh(&rose_route_list_lock);
 		rose_link_rx_restart(skb, rose_neigh, frametype);
-		goto out;
+		return res;
 	}
 
 	/*

=================================
[ INFO: inconsistent lock state ]
3.0.3 #2
---------------------------------
inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
kworker/1:1/20 [HC0[0]:SC1[1]:HE1:SE0] takes:
(rose_callsign_lock){+.?...}, at: [<ffffffffa0583128>] rose_get_neigh_callsign+0x28/0x80 [rose]
{SOFTIRQ-ON-W} state was registered at:

  [<ffffffff81096ef4>] __lock_acquire+0x5f4/0x1620
  [<ffffffff81098512>] lock_acquire+0xa2/0x120
  [<ffffffff813fec21>] _raw_spin_lock+0x31/0x40
  [<ffffffffa02ab068>] 0xffffffffa02ab068
  [<ffffffff81002043>] do_one_initcall+0x43/0x190
  [<ffffffff810a4730>] sys_init_module+0x90/0x1f0
  [<ffffffff81407592>] system_call_fastpath+0x16/0x1b
irq event stamp: 24814
hardirqs last  enabled at (24814): [<ffffffff813ff420>] _raw_spin_unlock_irqrestore+0x40/0x70
hardirqs last disabled at (24813): [<ffffffff813fed1e>] _raw_spin_lock_irqsave+0x2e/0x70
softirqs last  enabled at (24772): [<ffffffffa0184532>] mkiss_receive_buf+0x2e2/0x3dc [mkiss]
softirqs last disabled at (24773): [<ffffffff8140881c>] call_softirq+0x1c/0x30

other info that might help us debug this:

 Possible unsafe locking scenario:

       CPU0
       ----
  lock(rose_callsign_lock);
  <Interrupt>
    lock(rose_callsign_lock);

*** DEADLOCK ***

3 locks held by kworker/1:1/20:

 #0:  (events){.+.+.+}, at: [<ffffffff810772c7>] process_one_work+0x137/0x520
 #1:  ((&tty->buf.work)){+.+...}, at: [<ffffffff810772c7>] process_one_work+0x137/0x520
 #2:  (rcu_read_lock){.+.+..}, at: [<ffffffff81340a4b>] __netif_receive_skb+0xeb/0x6a0

stack backtrace:
Pid: 20, comm: kworker/1:1 Not tainted 3.0.3 #2
Call Trace:
 <IRQ>  [<ffffffff810953d5>] print_usage_bug+0x225/0x270
 [<ffffffff810961c3>] mark_lock+0x323/0x3f0
 [<ffffffff81096e7e>] __lock_acquire+0x57e/0x1620
 [<ffffffff81097413>] ? __lock_acquire+0xb13/0x1620
 [<ffffffff81018fbf>] ? save_stack_trace+0x2f/0x50
 [<ffffffff81098512>] lock_acquire+0xa2/0x120
 [<ffffffffa0583128>] ? rose_get_neigh_callsign+0x28/0x80 [rose]
 [<ffffffff813fec21>] _raw_spin_lock+0x31/0x40
 [<ffffffffa0583128>] ? rose_get_neigh_callsign+0x28/0x80 [rose]
 [<ffffffff81096525>] ? trace_hardirqs_on_caller+0x65/0x180
 [<ffffffffa0583128>] rose_get_neigh_callsign+0x28/0x80 [rose]
 [<ffffffffa05832d3>] rose_send_frame+0x33/0xb0 [rose]
 [<ffffffff81333446>] ? skb_dequeue+0x66/0x90
 [<ffffffffa058366b>] rose_link_rx_restart+0x6b/0x170 [rose]
 [<ffffffffa0584dc7>] rose_route_frame+0x187/0x6f0 [rose]
 [<ffffffff8106ab6c>] ? lock_timer_base+0x3c/0x70
 [<ffffffffa056a96c>] ? ax25_protocol_function+0x1c/0x70 [ax25]
 [<ffffffff813ff420>] ? _raw_spin_unlock_irqrestore+0x40/0x70
 [<ffffffffa0584c40>] ? rose_link_failed+0x90/0x90 [rose]
 [<ffffffffa056b8f7>] ax25_rx_iframe+0x77/0x350 [ax25]
 [<ffffffffa056df6e>] ax25_std_frame_in+0x8be/0x920 [ax25]
 [<ffffffffa057141c>] ? ax25_find_cb+0xcc/0x120 [ax25]
 [<ffffffffa056b1da>] ax25_rcv+0x3aa/0x9a0 [ax25]
 [<ffffffff810962fb>] ? mark_held_locks+0x6b/0xa0
 [<ffffffff813ff420>] ? _raw_spin_unlock_irqrestore+0x40/0x70
 [<ffffffff8132f18a>] ? sock_def_readable+0x8a/0xb0
 [<ffffffff8132f100>] ? sock_get_timestamp+0xc0/0xc0
 [<ffffffffa056b86f>] ax25_kiss_rcv+0x9f/0xb0 [ax25]
 [<ffffffff81340b6d>] __netif_receive_skb+0x20d/0x6a0
 [<ffffffff81340a4b>] ? __netif_receive_skb+0xeb/0x6a0
 [<ffffffff813410d4>] process_backlog+0xd4/0x1e0
 [<ffffffff81342c75>] net_rx_action+0x125/0x280
 [<ffffffff81062196>] __do_softirq+0xc6/0x210
 [<ffffffff8140881c>] call_softirq+0x1c/0x30
 <EOI>  [<ffffffff8100d43d>] ? do_softirq+0x9d/0xd0
 [<ffffffffa0184532>] ? mkiss_receive_buf+0x2e2/0x3dc [mkiss]
 [<ffffffff81062efb>] local_bh_enable_ip+0xeb/0xf0
 [<ffffffff813ff394>] _raw_spin_unlock_bh+0x34/0x40
 [<ffffffffa0184532>] mkiss_receive_buf+0x2e2/0x3dc [mkiss]
 [<ffffffff812a602a>] flush_to_ldisc+0x18a/0x1a0
 [<ffffffff81077336>] process_one_work+0x1a6/0x520
 [<ffffffff810772c7>] ? process_one_work+0x137/0x520
 [<ffffffff812a5ea0>] ? tty_schedule_flip+0x60/0x60
 [<ffffffff81079ca3>] worker_thread+0x173/0x400
 [<ffffffff81079b30>] ? manage_workers+0x210/0x210
 [<ffffffff8107e8a6>] kthread+0xb6/0xc0
 [<ffffffff810965fd>] ? trace_hardirqs_on_caller+0x13d/0x180
 [<ffffffff81408724>] kernel_thread_helper+0x4/0x10
 [<ffffffff813ff7d4>] ? retint_restore_args+0x13/0x13
 [<ffffffff8107e7f0>] ? __init_kthread_worker+0x70/0x70
 [<ffffffff81408720>] ? gs_change+0x13/0x13