On Thu, Aug 03, 2006 at 03:35:04PM +0100, Joao Barros wrote:
J> I recently switched ISPs which in turn led me from a cablemodem to an
J> ADSL modem.
J> After setting PPPoE up I started noticing this messages in the daily
J> run outputs that that nice guy Charlie root sends me at 3am:
J>
J> Aug 3 08:24:54 ultra5 kernel: session in wrong state
J>
J> I was a bit suspicious of anything PPPoE related and a little search
J> confirmed that, pointing directly at ng_pppoe.c
J> Being this a cryptic message to say the least and to probably save
J> someone some time when presented with this message I attach a patch
J> that adds the header "pppoe:" in every printf that didn't have it,
J> making it consistent with the rest of the file.
J> I also noticed this message appears right before the ISP closes the
J> connection due to time limit.
J>
J> I'm CCing those I see were the last ones to commit to this file and
J> will file a PR if asked to.
I've attached a patch that cleans a bit logging in ng_pppoe. It changes
all printf(9) to log(9). The latter is better since it spams console
less, if event occurs many times per second. Also I've made the messages
more clear - prepended node ID where possible, function name when it
starts with ng_pppoe, or just "ng_pppoe".
Can you please try out this patch and tell whether you like it. If you
do I will commit it soon.
------------------------------------------------------------------------
Index: ng_pppoe.c
===================================================================
RCS file: /home/ncvs/src/sys/netgraph/ng_pppoe.c,v
retrieving revision 1.78
diff -u -p -r1.78 ng_pppoe.c
--- ng_pppoe.c 27 Jan 2006 10:56:22 -0000 1.78
+++ ng_pppoe.c 4 Aug 2006 15:00:30 -0000
@@ -48,6 +48,7 @@
#include <sys/mbuf.h>
#include <sys/malloc.h>
#include <sys/errno.h>
+#include <sys/syslog.h>
#include <net/ethernet.h>
#include <netgraph/ng_message.h>
@@ -261,7 +262,7 @@ union uniq {
#define LEAVE(x) do { error = x; goto quit; } while(0)
static void pppoe_start(sessp sp);
-static void sendpacket(sessp sp);
+static void ng_pppoe_sendpacket(sessp sp);
static void pppoe_ticker(node_p node, hook_p hook, void *arg1, int arg2);
static const struct pppoe_tag *scan_tags(sessp sp,
const struct pppoe_hdr* ph);
@@ -383,7 +384,8 @@ insert_tag(sessp sp, const struct pppoe_
if ((i = neg->numtags++) < NUMTAGS) {
neg->tags[i] = tp;
} else {
- printf("pppoe: asked to add too many tags to packet\n");
+ log(LOG_NOTICE, "ng_pppoe: asked to add too many tags to "
+ "packet\n");
neg->numtags--;
}
}
@@ -406,7 +408,7 @@ make_packet(sessp sp) {
uint16_t length = 0;
KASSERT((sp->neg != NULL) && (sp->neg->m != NULL),
- ("%s: make_packet called from wrong state", __func__));
+ ("%s: called from wrong state", __func__));
CTR2(KTR_NET, "%20s: called %d", __func__, sp->Session_ID);
dp = (char *)wh->ph.tag;
@@ -415,7 +417,7 @@ make_packet(sessp sp) {
tag++, count++) {
tlen = ntohs((*tag)->tag_len) + sizeof(**tag);
if ((length + tlen) > (ETHER_MAX_LEN - 4 - sizeof(*wh))) {
- printf("pppoe: tags too long\n");
+ log(LOG_NOTICE, "ng_pppoe: tags too long\n");
sp->neg->numtags = count;
break; /* XXX chop off what's too long */
}
@@ -714,18 +716,21 @@ ng_pppoe_rcvmsg(node_p node, item_p item
case NGM_PPPOE_SERVICE:
ourmsg = (struct ngpppoe_init_data *)msg->data;
if (msg->header.arglen < sizeof(*ourmsg)) {
- printf("pppoe: init data too small\n");
+ log(LOG_ERR, "ng_pppoe[%x]: init data too "
+ "small\n", node->nd_ID);
LEAVE(EMSGSIZE);
}
if (msg->header.arglen - sizeof(*ourmsg) >
PPPOE_SERVICE_NAME_SIZE) {
- printf("pppoe_rcvmsg: service name too big");
+ log(LOG_ERR, "ng_pppoe[%x]: service name "
+ "too big\n", node->nd_ID);
LEAVE(EMSGSIZE);
}
if (msg->header.arglen - sizeof(*ourmsg) <
ourmsg->data_len) {
- printf("pppoe: init data has bad length,"
- " %d should be %zd\n", ourmsg->data_len,
+ log(LOG_ERR, "ng_pppoe[%x]: init data has bad "
+ "length, %d should be %zd\n", node->nd_ID,
+ ourmsg->data_len,
msg->header.arglen - sizeof (*ourmsg));
LEAVE(EMSGSIZE);
}
@@ -767,7 +772,8 @@ ng_pppoe_rcvmsg(node_p node, item_p item
break;
if (sp->state != PPPOE_SNONE) {
- printf("pppoe: Session already active\n");
+ log(LOG_NOTICE, "ng_pppoe[%x]: Session already "
+ "active\n", node->nd_ID);
LEAVE(EISCONN);
}
@@ -882,7 +888,8 @@ ng_pppoe_rcvmsg(node_p node, item_p item
* If you do it twice you just overwrite.
*/
if (sp->state != PPPOE_PRIMED) {
- printf("pppoe: Session not primed\n");
+ log(LOG_NOTICE, "ng_pppoe[%x]: session not "
+ "primed\n", node->nd_ID);
LEAVE(EISCONN);
}
neg = sp->neg;
@@ -1012,7 +1019,7 @@ pppoe_start(sessp sp)
insert_tag(sp, &uniqtag.hdr);
insert_tag(sp, &sp->neg->service.hdr);
make_packet(sp);
- sendpacket(sp);
+ ng_pppoe_sendpacket(sp);
}
static int
@@ -1105,7 +1112,8 @@ ng_pppoe_rcvdata(hook_p hook, item_p ite
if( m->m_len < sizeof(*wh)) {
m = m_pullup(m, sizeof(*wh)); /* Checks length */
if (m == NULL) {
- printf("couldn't m_pullup\n");
+ log(LOG_NOTICE, "ng_pppoe[%x]: couldn't "
+ "m_pullup(wh)\n", node->nd_ID);
LEAVE(ENOBUFS);
}
}
@@ -1124,7 +1132,10 @@ ng_pppoe_rcvdata(hook_p hook, item_p ite
if( m->m_len < m->m_pkthdr.len) {
m = m_pullup(m, m->m_pkthdr.len);
if (m == NULL) {
- printf("couldn't m_pullup\n");
+ log(LOG_NOTICE, "ng_pppoe[%x]: "
+ "couldn't "
+ "m_pullup(pkthdr)\n",
+ node->nd_ID);
LEAVE(ENOBUFS);
}
}
@@ -1147,7 +1158,8 @@ ng_pppoe_rcvdata(hook_p hook, item_p ite
}
}
if (m == NULL) {
- printf("packet fragmented\n");
+ log(LOG_NOTICE, "ng_pppoe[%x]: packet "
+ "fragmented\n", node->nd_ID);
LEAVE(EMSGSIZE);
}
}
@@ -1204,13 +1216,15 @@ ng_pppoe_rcvdata(hook_p hook, item_p ite
utag = get_tag(ph, PTT_HOST_UNIQ);
if ((utag == NULL)
|| (ntohs(utag->tag_len) != sizeof(sp))) {
- printf("no host unique field\n");
+ log(LOG_NOTICE, "ng_pppoe[%x]: no host "
+ "unique field\n", node->nd_ID);
LEAVE(ENETUNREACH);
}
sendhook = pppoe_finduniq(node, utag);
if (sendhook == NULL) {
- printf("no matching session\n");
+ log(LOG_NOTICE, "ng_pppoe[%x]: no "
+ "matching session\n", node->nd_ID);
LEAVE(ENETUNREACH);
}
@@ -1220,7 +1234,8 @@ ng_pppoe_rcvdata(hook_p hook, item_p ite
*/
sp = NG_HOOK_PRIVATE(sendhook);
if (sp->state != PPPOE_SINIT) {
- printf("session in wrong state\n");
+ log(LOG_NOTICE, "ng_pppoe[%x]: session "
+ "in wrong state\n", node->nd_ID);
LEAVE(ENETUNREACH);
}
neg = sp->neg;
@@ -1249,7 +1264,7 @@ ng_pppoe_rcvdata(hook_p hook, item_p ite
scan_tags(sp, ph);
make_packet(sp);
sp->state = PPPOE_SREQ;
- sendpacket(sp);
+ ng_pppoe_sendpacket(sp);
break;
case PADR_CODE:
@@ -1311,7 +1326,7 @@ ng_pppoe_rcvdata(hook_p hook, item_p ite
scan_tags(sp, ph);
make_packet(sp);
sp->state = PPPOE_NEWCONNECTED;
- sendpacket(sp);
+ ng_pppoe_sendpacket(sp);
/*
* Having sent the last Negotiation header,
* Set up the stored packet header to
@@ -1560,7 +1575,7 @@ ng_pppoe_rcvdata(hook_p hook, item_p ite
insert_tag(sp, &uniqtag.hdr);
scan_tags(sp, ph);
make_packet(sp);
- sendpacket(sp);
+ ng_pppoe_sendpacket(sp);
break;
/*
@@ -1655,8 +1670,9 @@ ng_pppoe_disconnect(hook_p hook)
/* Generate a packet of that type. */
MGETHDR(m, M_DONTWAIT, MT_DATA);
- if(m == NULL)
- printf("pppoe: Session out of mbufs\n");
+ if (m == NULL)
+ log(LOG_NOTICE, "ng_pppoe[%x]: session out of "
+ "mbufs\n", node->nd_ID);
else {
m->m_pkthdr.rcvif = NULL;
m->m_pkthdr.len = m->m_len = sizeof(*wh);
@@ -1749,13 +1765,14 @@ pppoe_ticker(node_p node, hook_p hook, v
break;
default:
/* Timeouts have no meaning in other states. */
- printf("pppoe: unexpected timeout\n");
+ log(LOG_NOTICE, "ng_pppoe[%x]: unexpected timeout\n",
+ node->nd_ID);
}
}
static void
-sendpacket(sessp sp)
+ng_pppoe_sendpacket(sessp sp)
{
struct mbuf *m0 = NULL;
hook_p hook = sp->hook;
@@ -1770,7 +1787,8 @@ sendpacket(sessp sp)
case PPPOE_DEAD:
case PPPOE_SNONE:
case PPPOE_CONNECTED:
- printf("pppoe: sendpacket: unexpected state\n");
+ log(LOG_NOTICE, "%s: unexpected state %d\n",
+ __func__, sp->state);
break;
case PPPOE_NEWCONNECTED:
@@ -1807,7 +1825,7 @@ sendpacket(sessp sp)
default:
error = EINVAL;
- printf("pppoe: timeout: bad state\n");
+ log(LOG_NOTICE, "%s: bad state %d\n", __func__, sp->state);
}
}
