Re: Odd log message associated with NFS
On Wed, Mar 28, 2007 at 07:23:48PM -0400, J. Bruce Fields wrote: > On Wed, Mar 28, 2007 at 07:05:36PM +, Thorsten Kranzkowski wrote: > > I'll let a tcpdump run this evening and see if I can correlate the message > > with anything. > > > > If you have a printk or other patch for me to try, just let me know. > > Well, just for fun, you could try something like this--should dump some > data the first time it hits the "bad direction" error. Time to check my iptables setup it seems Thanks for the lesson ;-) The source address obviously isn't from my local net, and the clear text speaks for itself. looks like an attack to some Windows service with phishing content. luckily this machine is neither windows based nor intel compatible :) bye, Thorsten Mar 30 18:29:54 Marvin kernel: svc: bad direction 268435456, dropping request Mar 30 18:29:54 Marvin kernel: dumping request; rq_addr = 61.180.228.240, port=59653, rq_deferred = , rq_arg: Mar 30 18:29:54 Marvin kernel: buf->head[0].iov_base = fc0008ea8850, buf->head[0].iov_len = 887 Mar 30 18:29:54 Marvin kernel: buf->tail[0].iov_base = , buf->tail[0].iov_len = 0 Mar 30 18:29:54 Marvin kernel: pages = fc000b1bd168, page_base = 0, page_len = 0 Mar 30 18:29:54 Marvin kernel: buflen = 0, len = 899 Mar 30 18:29:54 Marvin kernel: head data (from fc0008ea8844): Mar 30 18:29:54 Marvin kernel: RPC: print_hexl: length 899 Mar 30 18:29:54 Marvin kernel: : 0400 2800 1000 ..(. Mar 30 18:29:54 Marvin kernel: 0010: f891 7b5a 00ff d011 ..{Z Mar 30 18:29:54 Marvin kernel: 0020: a9b2 00c0 4fb6 e6fc O... Mar 30 18:29:54 Marvin kernel: 0030: 0100 Mar 30 18:29:54 Marvin kernel: 0040: 3303 ..3. Mar 30 18:29:54 Marvin kernel: 0050: 1000 1000 5359 5354 SYST Mar 30 18:29:54 Marvin kernel: 0060: 454d 1000 EM.. Mar 30 18:29:54 Marvin kernel: 0070: 1000 414c 4552 5400 ALERT... Mar 30 18:29:54 Marvin kernel: 0080: ef02 Mar 30 18:29:54 Marvin kernel: 0090: ef02 596f 7572 2073 7973 7465 6d20 Your system Mar 30 18:29:54 Marvin kernel: 00a0: 7265 6769 7374 7279 2069 7320 636f 7272 registry is corr Mar 30 18:29:54 Marvin kernel: 00b0: 7570 7465 6420 616e 6420 6e65 6564 7320 upted and needs Mar 30 18:29:54 Marvin kernel: 00c0: 746f 2062 6520 636c 6561 6e65 6420 696d to be cleaned im Mar 30 18:29:54 Marvin kernel: 00d0: 6d65 6469 6174 656c 792e 0a0a 0a43 6f6d mediatelyCom Mar 30 18:29:54 Marvin kernel: 00e0: 7072 6f6d 6973 6564 2072 6567 6973 7472 promised registr Mar 30 18:29:54 Marvin kernel: 00f0: 7920 6669 6c65 7320 6361 6e20 6c65 6164 y files can lead Mar 30 18:29:54 Marvin kernel: 0100: 2074 6f20 7468 6520 666f 6c6c 6f77 696e to the followin Mar 30 18:29:54 Marvin kernel: 0110: 673a 0a0a 312e 2043 6f6d 706c 6574 6520 g:..1. Complete Mar 30 18:29:54 Marvin kernel: 0120: 6163 6365 7373 206f 6620 796f 7572 2050 access of your P Mar 30 18:29:54 Marvin kernel: 0130: 4320 6279 2068 6163 6b65 7273 0a32 2e20 C by hackers.2. Mar 30 18:29:54 Marvin kernel: 0140: 536c 6f77 2073 7065 6564 7320 7265 7375 Slow speeds resu Mar 30 18:29:54 Marvin kernel: 0150: 6c74 696e 6720 696e 2073 6c6f 7720 646f lting in slow do Mar 30 18:29:54 Marvin kernel: 0160: 776e 6c6f 6164 7320 6f66 2069 6e74 6572 wnloads of inter Mar 30 18:29:54 Marvin kernel: 0170: 6e65 7420 6669 6c65 730a 332e 2054 6865 net files.3. The Mar 30 18:29:54 Marvin kernel: 0180: 2063 6f6d 7072 6f6d 6973 6520 6f66 2070 compromise of p Mar 30 18:29:54 Marvin kernel: 0190: 6572 736f 6e61 6c20 696e 666f 726d 6174 ersonal informat Mar 30 18:29:54 Marvin kernel: 01a0: 696f 6e20 7374 6f72 6564 206f 6e20 796f ion stored on yo Mar 30 18:29:54 Marvin kernel: 01b0: 7572 2063 6f6d 7075 7465 720a 342e 2043 ur computer.4. C Mar 30 18:29:54 Marvin kernel: 01c0: 6f6d 706c 6574 6520 7379 7374 656d 2066 omplete system f Mar 30 18:29:54 Marvin kernel: 01d0: 6169 6c75 7265 2072 6573 756c 7469 6e67 ailure resulting Mar 30 18:29:54 Marvin kernel: 01e0: 2069 6e20 7468 6520 6e65 6564 2066 6f72 in the need for Mar 30 18:29:54 Marvin kernel: 01f0: 2061 2063 6f6d 706c 6574 6520 7265 696e a complete rein Mar 30 18:29:54 Marvin kernel: 0200: 7374 616c 6c20 6f66 2079 6f75 7220 6861 stall of your ha Mar 30 18:29:54 Marvin kernel: 0210: 7264 2064 7269 7665 2e0a 0a54 6f20 6669 rd drive...To fi Mar 30 18:29:54 Marvin kernel: 0220: 7820 7468 6973 2070 726f 626c 656d 3a0a x this problem:. Mar 30 18:29:54 Marvin kernel: 0230: 0a31 2e20 4f70 656e 2049 6e74 6572 6e65 .1.
Re: Odd log message associated with NFS
On Fri, Mar 30, 2007 at 08:51:45PM +, Thorsten Kranzkowski wrote: > The source address obviously isn't from my local net, and the clear > text speaks for itself. Woah, yeah, neato. OK, I guess that makes me a lot more willing to believe any "impossible" error in linux/net/sunrpc/svc.c:svc_process() is due to random garbage on the network. I'd definitely like more people to be able to run their nfs server outside any firewall, so that probably means we should demote these printk's to dprintk's some day. > looks like an attack to some Windows service with phishing content. > luckily this machine is neither windows based nor intel compatible :) I'd love to know what the heck it's actually trying to do. Thanks for the followup! --b. - To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to [EMAIL PROTECTED] More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
Re: Odd log message associated with NFS
On Fri, Mar 30, 2007 at 08:51:45PM +, Thorsten Kranzkowski wrote: The source address obviously isn't from my local net, and the clear text speaks for itself. Woah, yeah, neato. OK, I guess that makes me a lot more willing to believe any impossible error in linux/net/sunrpc/svc.c:svc_process() is due to random garbage on the network. I'd definitely like more people to be able to run their nfs server outside any firewall, so that probably means we should demote these printk's to dprintk's some day. looks like an attack to some Windows service with phishing content. luckily this machine is neither windows based nor intel compatible :) I'd love to know what the heck it's actually trying to do. Thanks for the followup! --b. - To unsubscribe from this list: send the line unsubscribe linux-kernel in the body of a message to [EMAIL PROTECTED] More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
Re: Odd log message associated with NFS
On Wed, Mar 28, 2007 at 07:23:48PM -0400, J. Bruce Fields wrote: On Wed, Mar 28, 2007 at 07:05:36PM +, Thorsten Kranzkowski wrote: I'll let a tcpdump run this evening and see if I can correlate the message with anything. If you have a printk or other patch for me to try, just let me know. Well, just for fun, you could try something like this--should dump some data the first time it hits the bad direction error. Time to check my iptables setup it seems Thanks for the lesson ;-) The source address obviously isn't from my local net, and the clear text speaks for itself. looks like an attack to some Windows service with phishing content. luckily this machine is neither windows based nor intel compatible :) bye, Thorsten Mar 30 18:29:54 Marvin kernel: svc: bad direction 268435456, dropping request Mar 30 18:29:54 Marvin kernel: dumping request; rq_addr = 61.180.228.240, port=59653, rq_deferred = , rq_arg: Mar 30 18:29:54 Marvin kernel: buf-head[0].iov_base = fc0008ea8850, buf-head[0].iov_len = 887 Mar 30 18:29:54 Marvin kernel: buf-tail[0].iov_base = , buf-tail[0].iov_len = 0 Mar 30 18:29:54 Marvin kernel: pages = fc000b1bd168, page_base = 0, page_len = 0 Mar 30 18:29:54 Marvin kernel: buflen = 0, len = 899 Mar 30 18:29:54 Marvin kernel: head data (from fc0008ea8844): Mar 30 18:29:54 Marvin kernel: RPC: print_hexl: length 899 Mar 30 18:29:54 Marvin kernel: : 0400 2800 1000 ..(. Mar 30 18:29:54 Marvin kernel: 0010: f891 7b5a 00ff d011 ..{Z Mar 30 18:29:54 Marvin kernel: 0020: a9b2 00c0 4fb6 e6fc O... Mar 30 18:29:54 Marvin kernel: 0030: 0100 Mar 30 18:29:54 Marvin kernel: 0040: 3303 ..3. Mar 30 18:29:54 Marvin kernel: 0050: 1000 1000 5359 5354 SYST Mar 30 18:29:54 Marvin kernel: 0060: 454d 1000 EM.. Mar 30 18:29:54 Marvin kernel: 0070: 1000 414c 4552 5400 ALERT... Mar 30 18:29:54 Marvin kernel: 0080: ef02 Mar 30 18:29:54 Marvin kernel: 0090: ef02 596f 7572 2073 7973 7465 6d20 Your system Mar 30 18:29:54 Marvin kernel: 00a0: 7265 6769 7374 7279 2069 7320 636f 7272 registry is corr Mar 30 18:29:54 Marvin kernel: 00b0: 7570 7465 6420 616e 6420 6e65 6564 7320 upted and needs Mar 30 18:29:54 Marvin kernel: 00c0: 746f 2062 6520 636c 6561 6e65 6420 696d to be cleaned im Mar 30 18:29:54 Marvin kernel: 00d0: 6d65 6469 6174 656c 792e 0a0a 0a43 6f6d mediatelyCom Mar 30 18:29:54 Marvin kernel: 00e0: 7072 6f6d 6973 6564 2072 6567 6973 7472 promised registr Mar 30 18:29:54 Marvin kernel: 00f0: 7920 6669 6c65 7320 6361 6e20 6c65 6164 y files can lead Mar 30 18:29:54 Marvin kernel: 0100: 2074 6f20 7468 6520 666f 6c6c 6f77 696e to the followin Mar 30 18:29:54 Marvin kernel: 0110: 673a 0a0a 312e 2043 6f6d 706c 6574 6520 g:..1. Complete Mar 30 18:29:54 Marvin kernel: 0120: 6163 6365 7373 206f 6620 796f 7572 2050 access of your P Mar 30 18:29:54 Marvin kernel: 0130: 4320 6279 2068 6163 6b65 7273 0a32 2e20 C by hackers.2. Mar 30 18:29:54 Marvin kernel: 0140: 536c 6f77 2073 7065 6564 7320 7265 7375 Slow speeds resu Mar 30 18:29:54 Marvin kernel: 0150: 6c74 696e 6720 696e 2073 6c6f 7720 646f lting in slow do Mar 30 18:29:54 Marvin kernel: 0160: 776e 6c6f 6164 7320 6f66 2069 6e74 6572 wnloads of inter Mar 30 18:29:54 Marvin kernel: 0170: 6e65 7420 6669 6c65 730a 332e 2054 6865 net files.3. The Mar 30 18:29:54 Marvin kernel: 0180: 2063 6f6d 7072 6f6d 6973 6520 6f66 2070 compromise of p Mar 30 18:29:54 Marvin kernel: 0190: 6572 736f 6e61 6c20 696e 666f 726d 6174 ersonal informat Mar 30 18:29:54 Marvin kernel: 01a0: 696f 6e20 7374 6f72 6564 206f 6e20 796f ion stored on yo Mar 30 18:29:54 Marvin kernel: 01b0: 7572 2063 6f6d 7075 7465 720a 342e 2043 ur computer.4. C Mar 30 18:29:54 Marvin kernel: 01c0: 6f6d 706c 6574 6520 7379 7374 656d 2066 omplete system f Mar 30 18:29:54 Marvin kernel: 01d0: 6169 6c75 7265 2072 6573 756c 7469 6e67 ailure resulting Mar 30 18:29:54 Marvin kernel: 01e0: 2069 6e20 7468 6520 6e65 6564 2066 6f72 in the need for Mar 30 18:29:54 Marvin kernel: 01f0: 2061 2063 6f6d 706c 6574 6520 7265 696e a complete rein Mar 30 18:29:54 Marvin kernel: 0200: 7374 616c 6c20 6f66 2079 6f75 7220 6861 stall of your ha Mar 30 18:29:54 Marvin kernel: 0210: 7264 2064 7269 7665 2e0a 0a54 6f20 6669 rd drive...To fi Mar 30 18:29:54 Marvin kernel: 0220: 7820 7468 6973 2070 726f 626c 656d 3a0a x this problem:. Mar 30 18:29:54 Marvin kernel: 0230: 0a31 2e20 4f70 656e 2049 6e74 6572 6e65 .1. Open Interne Mar 30
Re: Odd log message associated with NFS
On Wed, Mar 28, 2007 at 07:05:36PM +, Thorsten Kranzkowski wrote: > I'll let a tcpdump run this evening and see if I can correlate the message > with anything. > > If you have a printk or other patch for me to try, just let me know. Well, just for fun, you could try something like this--should dump some data the first time it hits the "bad direction" error. --b. diff --git a/include/linux/sunrpc/xdr.h b/include/linux/sunrpc/xdr.h index 9e340fa..c2349d2 100644 --- a/include/linux/sunrpc/xdr.h +++ b/include/linux/sunrpc/xdr.h @@ -35,6 +35,45 @@ struct xdr_netobj { */ typedef int(*kxdrproc_t)(void *rqstp, __be32 *data, void *obj); +/* dump the buffer in `emacs-hexl' style */ +#define isprintable(c) ((c > 0x1f) && (c < 0x7f)) + +static inline void dump_hex(void *p, u_int length) +{ + u_int i, j, jm; + u8 c, *cp; + + printk("RPC: print_hexl: length %d\n",length); + cp = p; + + for (i = 0; i < length; i += 0x10) { + printk(" %04x: ", (u_int)i); + jm = length - i; + jm = jm > 16 ? 16 : jm; + + for (j = 0; j < jm; j++) { + if ((j % 2) == 1) + printk("%02x ", (u_int)cp[i+j]); + else + printk("%02x", (u_int)cp[i+j]); + } + for (; j < 16; j++) { + if ((j % 2) == 1) + printk(" "); + else + printk(" "); + } + printk(" "); + + for (j = 0; j < jm; j++) { + c = cp[i+j]; + c = isprintable(c) ? c : '.'; + printk("%c", c); + } + printk("\n"); + } +} + /* * Basic structure for transmission/reception of a client XDR message. * Features a header (for a linear buffer containing RPC headers @@ -61,6 +100,18 @@ struct xdr_buf { }; +static inline void dump_xdr_buf(struct xdr_buf *buf) +{ + printk("buf->head[0].iov_base = %p, buf->head[0].iov_len = %d\n", + buf->head[0].iov_base, buf->head[0].iov_len); + printk("buf->tail[0].iov_base = %p, buf->tail[0].iov_len = %d\n", + buf->tail[0].iov_base, buf->tail[0].iov_len); + printk("pages = %p, page_base = %d, page_len = %d\n", + buf->pages, buf->page_base, buf->page_len); + printk("buflen = %d, len = %d\n", buf->buflen, buf->len); + return; +} + /* * pre-xdr'ed macros. */ diff --git a/net/sunrpc/svc.c b/net/sunrpc/svc.c index b4db53f..977056e 100644 --- a/net/sunrpc/svc.c +++ b/net/sunrpc/svc.c @@ -776,6 +776,26 @@ svc_register(struct svc_serv *serv, int proto, unsigned short port) return error; } +static void +dump_once(struct svc_rqst *rqstp, __be32 *orig_start) +{ + static int done = 0; + struct kvec *argv = >rq_arg.head[0]; + char buf[RPC_MAX_ADDRBUFLEN]; + + if (done) + return; + done++; + + printk("dumping request; rq_addr = %s, rq_deferred = %p, rq_arg:\n", + svc_print_addr(rqstp, buf, sizeof(buf)), rqstp->rq_deferred); + dump_xdr_buf(>rq_arg); + + printk("head data (from %p):\n", orig_start); + dump_hex(orig_start, (argv->iov_base + argv->iov_len) + - (void *)orig_start); +} + /* * Process the RPC request. */ @@ -794,6 +814,7 @@ svc_process(struct svc_rqst *rqstp) __be32 auth_stat, rpc_stat; int auth_res; __be32 *reply_statp; + __be32 *start; rpc_stat = rpc_success; @@ -819,6 +840,7 @@ svc_process(struct svc_rqst *rqstp) if (rqstp->rq_prot == IPPROTO_TCP) svc_putnl(resv, 0); + start = argv->iov_base; rqstp->rq_xid = svc_getu32(argv); svc_putu32(resv, rqstp->rq_xid); @@ -971,6 +993,7 @@ err_short_len: err_bad_dir: if (net_ratelimit()) printk("svc: bad direction %d, dropping request\n", dir); + dump_once(rqstp, start); serv->sv_stats->rpcbadfmt++; goto dropit;/* drop request */ - To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to [EMAIL PROTECTED] More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
Re: Odd log message associated with NFS
On Wed, Mar 28, 2007 at 12:19:52PM +1000, Neil Brown wrote: > On Tuesday March 27, [EMAIL PROTECTED] wrote: > > On Tue, Mar 27, 2007 at 11:40:48AM -0700, Phy Prabab wrote: > > > kernel: rpcsvc: received unknown control message:-2144992132/-1 > > > > Just a 'me, too': > > For the 'unknown control message' messages, > see: "fix typo in svc_udp_recvfrom" previously on > [EMAIL PROTECTED] > > Fix is in -mm and below. will try, thanks. > For "svc: bad direction" Don't know... garbage on the net maybe? > Or maybe not. I have seen something like that before, but haven't I don't think so as it would mean corruption at other places, too. The Network is quite uninteresting: single ethernet segment, 2 switches involved, longest cable 8 meters ... > been able to pin it on anything yet. > NeilBrown I _had_ problems with the previous kernel (same version, same config, different (older) compiler (gcc 3.4.5 instead of 4.1.2), on both client and server) It would randomly (usually within 30 mins) 'lock up' NFS, where the client sends out requests but doesn't get any answer (apart from tcp-ack) from the server. Only a forced umount/remount recovered that (until the next lock-up). But I'm willing to attribute that to a somehow broken gcc. again, thanks for commenting. bye, Thorsten > --- linux-2.6.orig/net/sunrpc/svcsock.c > +++ linux-2.6/net/sunrpc/svcsock.c > @@ -779,7 +779,7 @@ svc_udp_recvfrom(struct svc_rqst *rqstp) > } > > clear_bit(SK_DATA, >sk_flags); > - while ((err == kernel_recvmsg(svsk->sk_sock, , NULL, > + while ((err = kernel_recvmsg(svsk->sk_sock, , NULL, > 0, 0, MSG_PEEK | MSG_DONTWAIT)) < 0 || > (skb = skb_recv_datagram(svsk->sk_sk, 0, 1, )) == NULL) { > if (err == -EAGAIN) { > > > > > > Mar 16 16:57:06 Marvin kernel: svc: bad direction 268435456, dropping > > request > > Mar 16 17:58:19 Marvin kernel: svc: bad direction 268435456, dropping > > request > > Mar 16 19:55:49 Marvin kernel: svc: bad direction 268435456, dropping > > request > > ... > > Mar 17 04:30:03 Marvin kernel: svc: bad direction 268435456, dropping > > request -- | Thorsten KranzkowskiInternet: [EMAIL PROTECTED] | | Mobile: ++49 170 1876134 Snail: Kiebitzstr. 14, 49324 Melle, Germany | | Ampr: [EMAIL PROTECTED], [EMAIL PROTECTED] [44.130.8.19] | - To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to [EMAIL PROTECTED] More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
Re: Odd log message associated with NFS
On Wed, Mar 28, 2007 at 12:59:25PM -0400, J. Bruce Fields wrote: > On Tue, Mar 27, 2007 at 07:39:10PM +, Thorsten Kranzkowski wrote: > > Mar 16 16:57:06 Marvin kernel: svc: bad direction 268435456, dropping > > request > > Mar 16 17:58:19 Marvin kernel: svc: bad direction 268435456, dropping > > request > > Mar 16 19:55:49 Marvin kernel: svc: bad direction 268435456, dropping > > request > > So that's 2^28, in a field that should always be zero. It's the very ahh. indeed. I didn't do the math, yet :) > first check of any data read from the rpc call, so it'd be consistent > with the call data being garbage, for one reason or another. > > What would cause that to happen, I don't know. Do you have a reliable > way to reproduce it? just sit and wait :-) I'll let a tcpdump run this evening and see if I can correlate the message with anything. If you have a printk or other patch for me to try, just let me know. bye, Thorsten -- | Thorsten KranzkowskiInternet: [EMAIL PROTECTED] | | Mobile: ++49 170 1876134 Snail: Kiebitzstr. 14, 49324 Melle, Germany | | Ampr: [EMAIL PROTECTED], [EMAIL PROTECTED] [44.130.8.19] | - To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to [EMAIL PROTECTED] More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
Re: Odd log message associated with NFS
On Tue, Mar 27, 2007 at 07:39:10PM +, Thorsten Kranzkowski wrote: > Mar 16 16:57:06 Marvin kernel: svc: bad direction 268435456, dropping request > Mar 16 17:58:19 Marvin kernel: svc: bad direction 268435456, dropping request > Mar 16 19:55:49 Marvin kernel: svc: bad direction 268435456, dropping request So that's 2^28, in a field that should always be zero. It's the very first check of any data read from the rpc call, so it'd be consistent with the call data being garbage, for one reason or another. What would cause that to happen, I don't know. Do you have a reliable way to reproduce it? --b. - To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to [EMAIL PROTECTED] More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
Re: Odd log message associated with NFS
On Tue, Mar 27, 2007 at 07:39:10PM +, Thorsten Kranzkowski wrote: Mar 16 16:57:06 Marvin kernel: svc: bad direction 268435456, dropping request Mar 16 17:58:19 Marvin kernel: svc: bad direction 268435456, dropping request Mar 16 19:55:49 Marvin kernel: svc: bad direction 268435456, dropping request So that's 2^28, in a field that should always be zero. It's the very first check of any data read from the rpc call, so it'd be consistent with the call data being garbage, for one reason or another. What would cause that to happen, I don't know. Do you have a reliable way to reproduce it? --b. - To unsubscribe from this list: send the line unsubscribe linux-kernel in the body of a message to [EMAIL PROTECTED] More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
Re: Odd log message associated with NFS
On Wed, Mar 28, 2007 at 12:59:25PM -0400, J. Bruce Fields wrote: On Tue, Mar 27, 2007 at 07:39:10PM +, Thorsten Kranzkowski wrote: Mar 16 16:57:06 Marvin kernel: svc: bad direction 268435456, dropping request Mar 16 17:58:19 Marvin kernel: svc: bad direction 268435456, dropping request Mar 16 19:55:49 Marvin kernel: svc: bad direction 268435456, dropping request So that's 2^28, in a field that should always be zero. It's the very ahh. indeed. I didn't do the math, yet :) first check of any data read from the rpc call, so it'd be consistent with the call data being garbage, for one reason or another. What would cause that to happen, I don't know. Do you have a reliable way to reproduce it? just sit and wait :-) I'll let a tcpdump run this evening and see if I can correlate the message with anything. If you have a printk or other patch for me to try, just let me know. bye, Thorsten -- | Thorsten KranzkowskiInternet: [EMAIL PROTECTED] | | Mobile: ++49 170 1876134 Snail: Kiebitzstr. 14, 49324 Melle, Germany | | Ampr: [EMAIL PROTECTED], [EMAIL PROTECTED] [44.130.8.19] | - To unsubscribe from this list: send the line unsubscribe linux-kernel in the body of a message to [EMAIL PROTECTED] More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
Re: Odd log message associated with NFS
On Wed, Mar 28, 2007 at 12:19:52PM +1000, Neil Brown wrote: On Tuesday March 27, [EMAIL PROTECTED] wrote: On Tue, Mar 27, 2007 at 11:40:48AM -0700, Phy Prabab wrote: kernel: rpcsvc: received unknown control message:-2144992132/-1 Just a 'me, too': For the 'unknown control message' messages, see: fix typo in svc_udp_recvfrom previously on [EMAIL PROTECTED] Fix is in -mm and below. will try, thanks. For svc: bad direction Don't know... garbage on the net maybe? Or maybe not. I have seen something like that before, but haven't I don't think so as it would mean corruption at other places, too. The Network is quite uninteresting: single ethernet segment, 2 switches involved, longest cable 8 meters ... been able to pin it on anything yet. NeilBrown I _had_ problems with the previous kernel (same version, same config, different (older) compiler (gcc 3.4.5 instead of 4.1.2), on both client and server) It would randomly (usually within 30 mins) 'lock up' NFS, where the client sends out requests but doesn't get any answer (apart from tcp-ack) from the server. Only a forced umount/remount recovered that (until the next lock-up). But I'm willing to attribute that to a somehow broken gcc. again, thanks for commenting. bye, Thorsten --- linux-2.6.orig/net/sunrpc/svcsock.c +++ linux-2.6/net/sunrpc/svcsock.c @@ -779,7 +779,7 @@ svc_udp_recvfrom(struct svc_rqst *rqstp) } clear_bit(SK_DATA, svsk-sk_flags); - while ((err == kernel_recvmsg(svsk-sk_sock, msg, NULL, + while ((err = kernel_recvmsg(svsk-sk_sock, msg, NULL, 0, 0, MSG_PEEK | MSG_DONTWAIT)) 0 || (skb = skb_recv_datagram(svsk-sk_sk, 0, 1, err)) == NULL) { if (err == -EAGAIN) { Mar 16 16:57:06 Marvin kernel: svc: bad direction 268435456, dropping request Mar 16 17:58:19 Marvin kernel: svc: bad direction 268435456, dropping request Mar 16 19:55:49 Marvin kernel: svc: bad direction 268435456, dropping request ... Mar 17 04:30:03 Marvin kernel: svc: bad direction 268435456, dropping request -- | Thorsten KranzkowskiInternet: [EMAIL PROTECTED] | | Mobile: ++49 170 1876134 Snail: Kiebitzstr. 14, 49324 Melle, Germany | | Ampr: [EMAIL PROTECTED], [EMAIL PROTECTED] [44.130.8.19] | - To unsubscribe from this list: send the line unsubscribe linux-kernel in the body of a message to [EMAIL PROTECTED] More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
Re: Odd log message associated with NFS
On Wed, Mar 28, 2007 at 07:05:36PM +, Thorsten Kranzkowski wrote: I'll let a tcpdump run this evening and see if I can correlate the message with anything. If you have a printk or other patch for me to try, just let me know. Well, just for fun, you could try something like this--should dump some data the first time it hits the bad direction error. --b. diff --git a/include/linux/sunrpc/xdr.h b/include/linux/sunrpc/xdr.h index 9e340fa..c2349d2 100644 --- a/include/linux/sunrpc/xdr.h +++ b/include/linux/sunrpc/xdr.h @@ -35,6 +35,45 @@ struct xdr_netobj { */ typedef int(*kxdrproc_t)(void *rqstp, __be32 *data, void *obj); +/* dump the buffer in `emacs-hexl' style */ +#define isprintable(c) ((c 0x1f) (c 0x7f)) + +static inline void dump_hex(void *p, u_int length) +{ + u_int i, j, jm; + u8 c, *cp; + + printk(RPC: print_hexl: length %d\n,length); + cp = p; + + for (i = 0; i length; i += 0x10) { + printk( %04x: , (u_int)i); + jm = length - i; + jm = jm 16 ? 16 : jm; + + for (j = 0; j jm; j++) { + if ((j % 2) == 1) + printk(%02x , (u_int)cp[i+j]); + else + printk(%02x, (u_int)cp[i+j]); + } + for (; j 16; j++) { + if ((j % 2) == 1) + printk( ); + else + printk( ); + } + printk( ); + + for (j = 0; j jm; j++) { + c = cp[i+j]; + c = isprintable(c) ? c : '.'; + printk(%c, c); + } + printk(\n); + } +} + /* * Basic structure for transmission/reception of a client XDR message. * Features a header (for a linear buffer containing RPC headers @@ -61,6 +100,18 @@ struct xdr_buf { }; +static inline void dump_xdr_buf(struct xdr_buf *buf) +{ + printk(buf-head[0].iov_base = %p, buf-head[0].iov_len = %d\n, + buf-head[0].iov_base, buf-head[0].iov_len); + printk(buf-tail[0].iov_base = %p, buf-tail[0].iov_len = %d\n, + buf-tail[0].iov_base, buf-tail[0].iov_len); + printk(pages = %p, page_base = %d, page_len = %d\n, + buf-pages, buf-page_base, buf-page_len); + printk(buflen = %d, len = %d\n, buf-buflen, buf-len); + return; +} + /* * pre-xdr'ed macros. */ diff --git a/net/sunrpc/svc.c b/net/sunrpc/svc.c index b4db53f..977056e 100644 --- a/net/sunrpc/svc.c +++ b/net/sunrpc/svc.c @@ -776,6 +776,26 @@ svc_register(struct svc_serv *serv, int proto, unsigned short port) return error; } +static void +dump_once(struct svc_rqst *rqstp, __be32 *orig_start) +{ + static int done = 0; + struct kvec *argv = rqstp-rq_arg.head[0]; + char buf[RPC_MAX_ADDRBUFLEN]; + + if (done) + return; + done++; + + printk(dumping request; rq_addr = %s, rq_deferred = %p, rq_arg:\n, + svc_print_addr(rqstp, buf, sizeof(buf)), rqstp-rq_deferred); + dump_xdr_buf(rqstp-rq_arg); + + printk(head data (from %p):\n, orig_start); + dump_hex(orig_start, (argv-iov_base + argv-iov_len) + - (void *)orig_start); +} + /* * Process the RPC request. */ @@ -794,6 +814,7 @@ svc_process(struct svc_rqst *rqstp) __be32 auth_stat, rpc_stat; int auth_res; __be32 *reply_statp; + __be32 *start; rpc_stat = rpc_success; @@ -819,6 +840,7 @@ svc_process(struct svc_rqst *rqstp) if (rqstp-rq_prot == IPPROTO_TCP) svc_putnl(resv, 0); + start = argv-iov_base; rqstp-rq_xid = svc_getu32(argv); svc_putu32(resv, rqstp-rq_xid); @@ -971,6 +993,7 @@ err_short_len: err_bad_dir: if (net_ratelimit()) printk(svc: bad direction %d, dropping request\n, dir); + dump_once(rqstp, start); serv-sv_stats-rpcbadfmt++; goto dropit;/* drop request */ - To unsubscribe from this list: send the line unsubscribe linux-kernel in the body of a message to [EMAIL PROTECTED] More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
Re: Odd log message associated with NFS
On Tuesday March 27, [EMAIL PROTECTED] wrote: > On Tue, Mar 27, 2007 at 11:40:48AM -0700, Phy Prabab wrote: > > Hello, > > > > I am currently running 2.6.21-rc5 and I am seeing quite a bit of this > > message in my log files: > > kernel: rpcsvc: received unknown control message:-2144992132/-1 > > > > This machine is an dual dual core opteron with 3Ware 9650 (14 disk > > RAID10), 4G RAM, 64bit kernel, nfsutils-1.0.12 running knfsd. This > > machine is a file server. > > Just a 'me, too': For the 'unknown control message' messages, see: "fix typo in svc_udp_recvfrom" previously on [EMAIL PROTECTED] Fix is in -mm and below. For "svc: bad direction" Don't know... garbage on the net maybe? Or maybe not. I have seen something like that before, but haven't been able to pin it on anything yet. NeilBrown --- linux-2.6.orig/net/sunrpc/svcsock.c +++ linux-2.6/net/sunrpc/svcsock.c @@ -779,7 +779,7 @@ svc_udp_recvfrom(struct svc_rqst *rqstp) } clear_bit(SK_DATA, >sk_flags); - while ((err == kernel_recvmsg(svsk->sk_sock, , NULL, + while ((err = kernel_recvmsg(svsk->sk_sock, , NULL, 0, 0, MSG_PEEK | MSG_DONTWAIT)) < 0 || (skb = skb_recv_datagram(svsk->sk_sk, 0, 1, )) == NULL) { if (err == -EAGAIN) { > > Mar 16 16:57:06 Marvin kernel: svc: bad direction 268435456, dropping request > Mar 16 17:58:19 Marvin kernel: svc: bad direction 268435456, dropping request > Mar 16 19:55:49 Marvin kernel: svc: bad direction 268435456, dropping request > ... > Mar 17 04:30:03 Marvin kernel: svc: bad direction 268435456, dropping request > Mar 17 06:28:52 Marvin kernel: pppd(795): unaligned trap at 02207f90: > 00011fd8d33d 29 1 > Mar 17 06:28:55 Marvin kernel: inet_sk_reselect_saddr(): shifting inet->saddr > from 82.149.xxx.xxx to 89.166.xxx.xxx > Mar 17 09:05:21 Marvin kernel: rpcsvc: received unknown control > message:-1024/186028080 > Mar 17 14:17:04 Marvin kernel: rpcsvc: received unknown control > message:-1024/186028040 > Mar 17 14:17:31 Marvin kernel: rpcsvc: received unknown control > message:-1024/186028040 > Mar 17 14:49:14 Marvin kernel: rpcsvc: received unknown control > message:-1024/186028080 > Mar 17 14:49:15 Marvin kernel: rpcsvc: received unknown control > message:-1024/186028040 > > > > This is from my little 'server', alpha ev4 'noname', 2.6.21-rc3, compiled > with gcc 4.1.2 > > client is mostly an alpha ev6 2.6.21-rc3, gcc 4.1.2. > > Apart from the messages NFS seems to run just fine currently. > > Bye, > Thorsten > > > > -- > | Thorsten KranzkowskiInternet: [EMAIL PROTECTED] > | > | Mobile: ++49 170 1876134 Snail: Kiebitzstr. 14, 49324 Melle, Germany > | > | Ampr: [EMAIL PROTECTED], [EMAIL PROTECTED] [44.130.8.19] | > - > To unsubscribe from this list: send the line "unsubscribe linux-kernel" in > the body of a message to [EMAIL PROTECTED] > More majordomo info at http://vger.kernel.org/majordomo-info.html > Please read the FAQ at http://www.tux.org/lkml/ - To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to [EMAIL PROTECTED] More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
Re: Odd log message associated with NFS
On Tue, Mar 27, 2007 at 11:40:48AM -0700, Phy Prabab wrote: > Hello, > > I am currently running 2.6.21-rc5 and I am seeing quite a bit of this > message in my log files: > kernel: rpcsvc: received unknown control message:-2144992132/-1 > > This machine is an dual dual core opteron with 3Ware 9650 (14 disk > RAID10), 4G RAM, 64bit kernel, nfsutils-1.0.12 running knfsd. This > machine is a file server. Just a 'me, too': Mar 16 16:57:06 Marvin kernel: svc: bad direction 268435456, dropping request Mar 16 17:58:19 Marvin kernel: svc: bad direction 268435456, dropping request Mar 16 19:55:49 Marvin kernel: svc: bad direction 268435456, dropping request ... Mar 17 04:30:03 Marvin kernel: svc: bad direction 268435456, dropping request Mar 17 06:28:52 Marvin kernel: pppd(795): unaligned trap at 02207f90: 00011fd8d33d 29 1 Mar 17 06:28:55 Marvin kernel: inet_sk_reselect_saddr(): shifting inet->saddr from 82.149.xxx.xxx to 89.166.xxx.xxx Mar 17 09:05:21 Marvin kernel: rpcsvc: received unknown control message:-1024/186028080 Mar 17 14:17:04 Marvin kernel: rpcsvc: received unknown control message:-1024/186028040 Mar 17 14:17:31 Marvin kernel: rpcsvc: received unknown control message:-1024/186028040 Mar 17 14:49:14 Marvin kernel: rpcsvc: received unknown control message:-1024/186028080 Mar 17 14:49:15 Marvin kernel: rpcsvc: received unknown control message:-1024/186028040 This is from my little 'server', alpha ev4 'noname', 2.6.21-rc3, compiled with gcc 4.1.2 client is mostly an alpha ev6 2.6.21-rc3, gcc 4.1.2. Apart from the messages NFS seems to run just fine currently. Bye, Thorsten -- | Thorsten KranzkowskiInternet: [EMAIL PROTECTED] | | Mobile: ++49 170 1876134 Snail: Kiebitzstr. 14, 49324 Melle, Germany | | Ampr: [EMAIL PROTECTED], [EMAIL PROTECTED] [44.130.8.19] | - To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to [EMAIL PROTECTED] More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
Re: Odd log message associated with NFS
On Tue, Mar 27, 2007 at 11:40:48AM -0700, Phy Prabab wrote: Hello, I am currently running 2.6.21-rc5 and I am seeing quite a bit of this message in my log files: kernel: rpcsvc: received unknown control message:-2144992132/-1 This machine is an dual dual core opteron with 3Ware 9650 (14 disk RAID10), 4G RAM, 64bit kernel, nfsutils-1.0.12 running knfsd. This machine is a file server. Just a 'me, too': Mar 16 16:57:06 Marvin kernel: svc: bad direction 268435456, dropping request Mar 16 17:58:19 Marvin kernel: svc: bad direction 268435456, dropping request Mar 16 19:55:49 Marvin kernel: svc: bad direction 268435456, dropping request ... Mar 17 04:30:03 Marvin kernel: svc: bad direction 268435456, dropping request Mar 17 06:28:52 Marvin kernel: pppd(795): unaligned trap at 02207f90: 00011fd8d33d 29 1 Mar 17 06:28:55 Marvin kernel: inet_sk_reselect_saddr(): shifting inet-saddr from 82.149.xxx.xxx to 89.166.xxx.xxx Mar 17 09:05:21 Marvin kernel: rpcsvc: received unknown control message:-1024/186028080 Mar 17 14:17:04 Marvin kernel: rpcsvc: received unknown control message:-1024/186028040 Mar 17 14:17:31 Marvin kernel: rpcsvc: received unknown control message:-1024/186028040 Mar 17 14:49:14 Marvin kernel: rpcsvc: received unknown control message:-1024/186028080 Mar 17 14:49:15 Marvin kernel: rpcsvc: received unknown control message:-1024/186028040 This is from my little 'server', alpha ev4 'noname', 2.6.21-rc3, compiled with gcc 4.1.2 client is mostly an alpha ev6 2.6.21-rc3, gcc 4.1.2. Apart from the messages NFS seems to run just fine currently. Bye, Thorsten -- | Thorsten KranzkowskiInternet: [EMAIL PROTECTED] | | Mobile: ++49 170 1876134 Snail: Kiebitzstr. 14, 49324 Melle, Germany | | Ampr: [EMAIL PROTECTED], [EMAIL PROTECTED] [44.130.8.19] | - To unsubscribe from this list: send the line unsubscribe linux-kernel in the body of a message to [EMAIL PROTECTED] More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/
Re: Odd log message associated with NFS
On Tuesday March 27, [EMAIL PROTECTED] wrote: On Tue, Mar 27, 2007 at 11:40:48AM -0700, Phy Prabab wrote: Hello, I am currently running 2.6.21-rc5 and I am seeing quite a bit of this message in my log files: kernel: rpcsvc: received unknown control message:-2144992132/-1 This machine is an dual dual core opteron with 3Ware 9650 (14 disk RAID10), 4G RAM, 64bit kernel, nfsutils-1.0.12 running knfsd. This machine is a file server. Just a 'me, too': For the 'unknown control message' messages, see: fix typo in svc_udp_recvfrom previously on [EMAIL PROTECTED] Fix is in -mm and below. For svc: bad direction Don't know... garbage on the net maybe? Or maybe not. I have seen something like that before, but haven't been able to pin it on anything yet. NeilBrown --- linux-2.6.orig/net/sunrpc/svcsock.c +++ linux-2.6/net/sunrpc/svcsock.c @@ -779,7 +779,7 @@ svc_udp_recvfrom(struct svc_rqst *rqstp) } clear_bit(SK_DATA, svsk-sk_flags); - while ((err == kernel_recvmsg(svsk-sk_sock, msg, NULL, + while ((err = kernel_recvmsg(svsk-sk_sock, msg, NULL, 0, 0, MSG_PEEK | MSG_DONTWAIT)) 0 || (skb = skb_recv_datagram(svsk-sk_sk, 0, 1, err)) == NULL) { if (err == -EAGAIN) { Mar 16 16:57:06 Marvin kernel: svc: bad direction 268435456, dropping request Mar 16 17:58:19 Marvin kernel: svc: bad direction 268435456, dropping request Mar 16 19:55:49 Marvin kernel: svc: bad direction 268435456, dropping request ... Mar 17 04:30:03 Marvin kernel: svc: bad direction 268435456, dropping request Mar 17 06:28:52 Marvin kernel: pppd(795): unaligned trap at 02207f90: 00011fd8d33d 29 1 Mar 17 06:28:55 Marvin kernel: inet_sk_reselect_saddr(): shifting inet-saddr from 82.149.xxx.xxx to 89.166.xxx.xxx Mar 17 09:05:21 Marvin kernel: rpcsvc: received unknown control message:-1024/186028080 Mar 17 14:17:04 Marvin kernel: rpcsvc: received unknown control message:-1024/186028040 Mar 17 14:17:31 Marvin kernel: rpcsvc: received unknown control message:-1024/186028040 Mar 17 14:49:14 Marvin kernel: rpcsvc: received unknown control message:-1024/186028080 Mar 17 14:49:15 Marvin kernel: rpcsvc: received unknown control message:-1024/186028040 This is from my little 'server', alpha ev4 'noname', 2.6.21-rc3, compiled with gcc 4.1.2 client is mostly an alpha ev6 2.6.21-rc3, gcc 4.1.2. Apart from the messages NFS seems to run just fine currently. Bye, Thorsten -- | Thorsten KranzkowskiInternet: [EMAIL PROTECTED] | | Mobile: ++49 170 1876134 Snail: Kiebitzstr. 14, 49324 Melle, Germany | | Ampr: [EMAIL PROTECTED], [EMAIL PROTECTED] [44.130.8.19] | - To unsubscribe from this list: send the line unsubscribe linux-kernel in the body of a message to [EMAIL PROTECTED] More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/ - To unsubscribe from this list: send the line unsubscribe linux-kernel in the body of a message to [EMAIL PROTECTED] More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/