2007-03-27 18:40:50

by Phy Prabab

[permalink] [raw]
Subject: Odd log message associated with NFS

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.

I checked google and found nothing that seemed related and I ran a
ethereal looking for anything out of the ordinary to no avail.

Any help is greatly appreciated.
TIA!
Phy

-------------------------------------------------------------------------
Take Surveys. Earn Cash. Influence the Future of IT
Join SourceForge.net's Techsay panel and you'll get the chance to share your
opinions on IT & business topics through brief surveys-and earn cash
http://www.techsay.com/default.php?page=join.php&p=sourceforge&CID=DEVDEV
_______________________________________________
NFS maillist - [email protected]
https://lists.sourceforge.net/lists/listinfo/nfs


2007-03-27 19:39:10

by Thorsten Kranzkowski

[permalink] [raw]
Subject: 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 0000020000207f90: 000000011fd8d33d 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 Kranzkowski Internet: [email protected] |
| Mobile: ++49 170 1876134 Snail: Kiebitzstr. 14, 49324 Melle, Germany |
| Ampr: dl8bcu@db0lj.#rpl.deu.eu, [email protected] [44.130.8.19] |

2007-03-28 16:59:25

by J. Bruce Fields

[permalink] [raw]
Subject: Re: Odd log message associated with NFS

On Tue, Mar 27, 2007 at 07:39:10PM +0000, 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.

2007-03-28 19:05:36

by Thorsten Kranzkowski

[permalink] [raw]
Subject: 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 +0000, 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 Kranzkowski Internet: [email protected] |
| Mobile: ++49 170 1876134 Snail: Kiebitzstr. 14, 49324 Melle, Germany |
| Ampr: dl8bcu@db0lj.#rpl.deu.eu, [email protected] [44.130.8.19] |

2007-03-28 23:23:53

by J. Bruce Fields

[permalink] [raw]
Subject: Re: Odd log message associated with NFS

On Wed, Mar 28, 2007 at 07:05:36PM +0000, 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 */

-------------------------------------------------------------------------
Take Surveys. Earn Cash. Influence the Future of IT
Join SourceForge.net's Techsay panel and you'll get the chance to share your
opinions on IT & business topics through brief surveys-and earn cash
http://www.techsay.com/default.php?page=join.php&p=sourceforge&CID=DEVDEV
_______________________________________________
NFS maillist - [email protected]
https://lists.sourceforge.net/lists/listinfo/nfs

2007-03-30 20:51:45

by Thorsten Kranzkowski

[permalink] [raw]
Subject: 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 +0000, 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 = 0000000000000000, rq_arg:
Mar 30 18:29:54 Marvin kernel: buf->head[0].iov_base = fffffc0008ea8850, buf->head[0].iov_len = 887
Mar 30 18:29:54 Marvin kernel: buf->tail[0].iov_base = 0000000000000000, buf->tail[0].iov_len = 0
Mar 30 18:29:54 Marvin kernel: pages = fffffc000b1bd168, 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 fffffc0008ea8844):
Mar 30 18:29:54 Marvin kernel: RPC: print_hexl: length 899
Mar 30 18:29:54 Marvin kernel: 0000: 0400 2800 1000 0000 0000 0000 0000 0000 ..(.............
Mar 30 18:29:54 Marvin kernel: 0010: 0000 0000 0000 0000 f891 7b5a 00ff d011 ..........{Z....
Mar 30 18:29:54 Marvin kernel: 0020: a9b2 00c0 4fb6 e6fc 0000 0000 0000 0000 ....O...........
Mar 30 18:29:54 Marvin kernel: 0030: 0000 0000 0000 0000 0000 0000 0100 0000 ................
Mar 30 18:29:54 Marvin kernel: 0040: 0000 0000 0000 ffff ffff 3303 0000 0000 ..........3.....
Mar 30 18:29:54 Marvin kernel: 0050: 1000 0000 0000 0000 1000 0000 5359 5354 ............SYST
Mar 30 18:29:54 Marvin kernel: 0060: 454d 0000 0000 0000 0000 0000 1000 0000 EM..............
Mar 30 18:29:54 Marvin kernel: 0070: 0000 0000 1000 0000 414c 4552 5400 0000 ........ALERT...
Mar 30 18:29:54 Marvin kernel: 0080: 0000 0000 0000 0000 ef02 0000 0000 0000 ................
Mar 30 18:29:54 Marvin kernel: 0090: ef02 0000 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 mediately....Com
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 18:29:54 Marvin kernel: 0240: 7420 4578 706c 6f72 6572 0a32 2e20 496e t Explorer.2. In
Mar 30 18:29:54 Marvin kernel: 0250: 2074 6865 2055 524c 2046 6965 6c64 2074 the URL Field t
Mar 30 18:29:54 Marvin kernel: 0260: 7970 6520 2d20 2052 6567 5570 6461 7469 ype - RegUpdati
Mar 30 18:29:54 Marvin kernel: 0270: 6e67 2e63 6f6d 0a33 2e20 4e6f 7465 2074 ng.com.3. Note t
Mar 30 18:29:54 Marvin kernel: 0280: 6861 7420 616c 6c20 7665 7273 696f 6e73 hat all versions
Mar 30 18:29:54 Marvin kernel: 0290: 206f 6620 7769 6e64 6f77 7320 6172 6520 of windows are
Mar 30 18:29:54 Marvin kernel: 02a0: 7375 7070 6f72 2074 6564 2e0a 342e 204f suppor ted..4. O
Mar 30 18:29:54 Marvin kernel: 02b0: 6e63 6520 796f 7520 6c6f 6164 2074 6865 nce you load the
Mar 30 18:29:54 Marvin kernel: 02c0: 2070 726f 6772 616d 2c20 636c 6f73 6520 program, close
Mar 30 18:29:54 Marvin kernel: 02d0: 7468 6973 2077 696e 646f 772e 0a0a 506c this window...Pl
Mar 30 18:29:54 Marvin kernel: 02e0: 6561 7365 206e 6f74 6520 7468 6174 206f ease note that o
Mar 30 18:29:54 Marvin kernel: 02f0: 6e63 6520 796f 7520 7669 7369 7420 5265 nce you visit Re
Mar 30 18:29:54 Marvin kernel: 0300: 6755 7064 6174 696e 672e 636f 6d20 616e gUpdating.com an
Mar 30 18:29:54 Marvin kernel: 0310: 6420 696e 7374 616c 6c20 7468 6520 0a63 d install the .c
Mar 30 18:29:54 Marvin kernel: 0320: 6c65 616e 6572 2070 726f 6772 616d 2079 leaner program y
Mar 30 18:29:54 Marvin kernel: 0330: 6f75 2077 696c 6c20 6e6f 7420 7265 6365 ou will not rece
Mar 30 18:29:54 Marvin kernel: 0340: 6976 6520 616e 7920 6d6f 7265 2072 656d ive any more rem
Mar 30 18:29:54 Marvin kernel: 0350: 696e 6465 7273 206f 7220 706f 702d 7570 inders or pop-up
Mar 30 18:29:54 Marvin kernel: 0360: 7320 6c69 6b65 2074 6869 7320 6f6e 652e s like this one.
Mar 30 18:29:54 Marvin kernel: 0370: 0a0a 5265 6755 7064 6174 696e 672e 636f ..RegUpdating.co
Mar 30 18:29:54 Marvin kernel: 0380: 6d0a 00 m..


>
> --b.
>

--
| Thorsten Kranzkowski Internet: [email protected] |
| Mobile: ++49 170 1876134 Snail: Kiebitzstr. 14, 49324 Melle, Germany |
| Ampr: dl8bcu@db0lj.#rpl.deu.eu, [email protected] [44.130.8.19] |

2007-03-30 21:03:46

by J. Bruce Fields

[permalink] [raw]
Subject: Re: Odd log message associated with NFS

On Fri, Mar 30, 2007 at 08:51:45PM +0000, 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.

-------------------------------------------------------------------------
Take Surveys. Earn Cash. Influence the Future of IT
Join SourceForge.net's Techsay panel and you'll get the chance to share your
opinions on IT & business topics through brief surveys-and earn cash
http://www.techsay.com/default.php?page=join.php&p=sourceforge&CID=DEVDEV
_______________________________________________
NFS maillist - [email protected]
https://lists.sourceforge.net/lists/listinfo/nfs