From sec@yoda.fwe.pi.musin.de Mon Sep 10 06:35:36 2001 Return-Path: Received: from yoda.fwe.pi.musin.de (yoda.fwe.pi.musin.de [194.246.250.18]) by hub.freebsd.org (Postfix) with ESMTP id 48D5737B401 for ; Mon, 10 Sep 2001 06:35:35 -0700 (PDT) Received: (from sec@localhost) by yoda.fwe.pi.musin.de (8.11.6/8.11.4) id f8ADZWn75437; Mon, 10 Sep 2001 15:35:32 +0200 (CEST) (envelope-from sec) Message-Id: <200109101335.f8ADZWn75437@yoda.fwe.pi.musin.de> Date: Mon, 10 Sep 2001 15:35:32 +0200 (CEST) From: Stefan `Sec` Zehl Reply-To: Stefan `Sec` Zehl To: FreeBSD-gnats-submit@freebsd.org Cc: Subject: rpc.rstatd consumed lots of open file descriptors X-Send-Pr-Version: 3.113 X-GNATS-Notify: >Number: 30484 >Category: bin >Synopsis: rpc.rstatd consumed lots of open file descriptors >Confidential: no >Severity: non-critical >Priority: low >Responsible: freebsd-bugs >State: closed >Quarter: >Keywords: >Date-Required: >Class: sw-bug >Submitter-Id: current-users >Arrival-Date: Mon Sep 10 06:40:01 PDT 2001 >Closed-Date: Fri Dec 06 20:52:17 PST 2002 >Last-Modified: Fri Dec 06 20:52:17 PST 2002 >Originator: Stefan `Sec` Zehl >Release: FreeBSD 4.4-RC i386 >Organization: >Environment: System: FreeBSD yoda 4.4-RC FreeBSD 4.4-RC #5: Sun Aug 19 13:22:01 CEST 2001 root@yoda:/usr/obj/usr/src/sys/YODA i386 last make world on 1.Sep - have not rebooted yet. >Description: Today my machine expirienced lots of problems since all maximum number of open files was reached. This resulted in amusing messages like: lsof: can't open pipes: Too many open files in system ps: /dev/null: Too many open files in system and others. I wasn't able to execute any program (besides shell-builtins) After killing a few programs i found that 'rpc.rstatd' was the source of the problem. lsof showed that it had consumed them all to open /dev/mem and /dev/kmem: [...] rpc.rstat 58933 root 383r VCHR 2,1 0xc035c524 6293 /dev/kmem rpc.rstat 58933 root 384r VCHR 2,0 0t0 6294 /dev/mem rpc.rstat 58933 root 385r VCHR 2,1 0xc035c524 6293 /dev/kmem rpc.rstat 58933 root 386r VCHR 2,0 0t0 6294 /dev/mem rpc.rstat 58933 root 387r VCHR 2,1 0xc035c524 6293 /dev/kmem rpc.rstat 58933 root 388r VCHR 2,0 0t0 6294 /dev/mem rpc.rstat 58933 root 389r VCHR 2,1 0xc035c524 6293 /dev/kmem after killing it, the problem ceased. >How-To-Repeat: I have rpc.rstatd enabled in the inetd.conf, and query it regularely using xosview using a command line like this: xsysstats -allnames -split 1x3 -display :0 -window 1 -type cpu -color red -window 2 -type disk -color red -window 3 -type packets -color red -samescale -host This has happened the first time, so I can't really reproduce it. I will cvsup today and try with a brand new kernel and world and see if thet problem happens again. I figured I send this now even though its incomplete, because the release is so close, and you might want to look into it. >Fix: Have ddb in the kernel so you can find the pid of your rpc.rstatd :-> >Release-Note: >Audit-Trail: From: Stefan `Sec` Zehl To: freebsd-gnats-submit@FreeBSD.org, freebsd-bugs@FreeBSD.org Cc: Subject: Re: bin/30484: rpc.rstatd consumed lots of open file descriptors Date: Tue, 11 Sep 2001 13:33:36 +0200 Hi, I investigated that problem a little further. I cvsup'd yesterday, and did a fresh make world and rebooted. FreeBSD yoda 4.4-RC FreeBSD 4.4-RC #0: Mon Sep 10 20:24:01 CEST 2001 root@yoda:/usr/obj/usr/src/sys/YODA i386 The problem does persist. I start rpc.rstatd and xsysstats. and wait a few minutes. Lsof then shows that filedescriptor leakage, The filedescriptors remain open even if I kill "xsysstats" so this program can't be the culprit. yoda:~#lsof -p 1729 COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME rpc.rstat 1729 root cwd VDIR 13,131072 512 2 / rpc.rstat 1729 root rtd VDIR 13,131072 512 2 / rpc.rstat 1729 root txt VREG 13,131077 9308 379346 /usr/libexec/rpc.rstatd rpc.rstat 1729 root txt VREG 13,131077 77224 379406 /usr/libexec/ld-elf.so.1 rpc.rstat 1729 root txt VREG 13,131077 30864 349800 /usr/lib/librpcsvc.so.2 rpc.rstat 1729 root txt VREG 13,131077 33200 349705 /usr/lib/libutil.so.3 rpc.rstat 1729 root txt VREG 13,131077 19360 349517 /usr/lib/libkvm.so.2 rpc.rstat 1729 root txt VREG 13,131077 12296 349397 /usr/lib/libdevstat.so.2 rpc.rstat 1729 root txt VREG 13,131077 581324 349732 /usr/lib/libc.so.4 rpc.rstat 1729 root 0u VCHR 2,2 0t0 6295 /dev/null rpc.rstat 1729 root 1u VCHR 2,2 0t0 6295 /dev/null rpc.rstat 1729 root 2u VCHR 2,2 0t0 6295 /dev/null rpc.rstat 1729 root 3u IPv4 0xc577c6c0 0t0 UDP *:ircs rpc.rstat 1729 root 4r VCHR 2,0 0t0 6294 /dev/mem rpc.rstat 1729 root 5r VCHR 2,1 0xc035c8e4 6293 /dev/kmem rpc.rstat 1729 root 6r VCHR 2,0 0t0 6294 /dev/mem rpc.rstat 1729 root 7r VCHR 2,1 0xc035c8e4 6293 /dev/kmem [...] rpc.rstat 1729 root 48r VCHR 2,0 0t0 6294 /dev/mem rpc.rstat 1729 root 49r VCHR 2,1 0xc035c8e4 6293 /dev/kmem I have a ktrace output of a run, but it is rather large, so I will send the full output only on request. The last part is: 1729 rpc.rstatd CALL socket(0x2,0x2,0x11) 1729 rpc.rstatd RET socket 50/0x32 1729 rpc.rstatd CALL getsockname(0x32,0xbfbff080,0xbfbff07c) 1729 rpc.rstatd RET getsockname 0 1729 rpc.rstatd CALL getsockopt(0x32,0,0x13,0xbfbff074,0xbfbff078) 1729 rpc.rstatd RET getsockopt 0 1729 rpc.rstatd CALL setsockopt(0x32,0,0x13,0xbfbff070,0x4) 1729 rpc.rstatd RET setsockopt 0 1729 rpc.rstatd CALL bind(0x32,0xbfbff080,0x10) 1729 rpc.rstatd RET bind 0 1729 rpc.rstatd CALL ioctl(0x32,FIONBIO,0xbfbff164) 1729 rpc.rstatd RET ioctl 0 1729 rpc.rstatd CALL sendto(0x32,0x806b1f8,0x38,0,0x806b008,0x10) 1729 rpc.rstatd GIO fd 50 wrote 56 bytes "\M^E+\^^Ï\0\0\0\0\0\0\0\^B\0\^A\M^F\240\0\0\0\^B\0\0\0\^B\0\0\0\0\0\0\ \0\0\0\0\0\0\0\0\0\0\0\^A\M^F¡\0\0\0\^B\0\0\0\0\0\0\0\0" 1729 rpc.rstatd RET sendto 56/0x38 1729 rpc.rstatd CALL gettimeofday(0xbfbff0b0,0) 1729 rpc.rstatd RET gettimeofday 0 1729 rpc.rstatd CALL select(0x33,0xbfbff120,0,0,0xbfbff0a8) 1729 rpc.rstatd RET select 1 1729 rpc.rstatd CALL recvfrom(0x32,0x806b068,0x190,0,0xbfbff110,0xbfbff08c) 1729 rpc.rstatd GIO fd 50 read 28 bytes "\M^E+\^^Ï\0\0\0\^A\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\^A" 1729 rpc.rstatd RET recvfrom 28/0x1c 1729 rpc.rstatd CALL close(0x32) 1729 rpc.rstatd RET close 0 1729 rpc.rstatd CALL close(0x32) 1729 rpc.rstatd RET close -1 errno 9 Bad file descriptor 1729 rpc.rstatd CALL stat(0x280ff8c0,0xbfbff1f0) 1729 rpc.rstatd NAMI "/var/run/portmapsock" 1729 rpc.rstatd RET stat -1 errno 2 No such file or directory 1729 rpc.rstatd CALL socket(0x2,0x2,0) 1729 rpc.rstatd RET socket 50/0x32 1729 rpc.rstatd CALL ioctl(0x32,SIOCGIFCONF,0xbfbfed98) 1729 rpc.rstatd RET ioctl 0 1729 rpc.rstatd CALL ioctl(0x32,SIOCGIFFLAGS,0xbfbfeda0) 1729 rpc.rstatd RET ioctl 0 1729 rpc.rstatd CALL ioctl(0x32,SIOCGIFFLAGS,0xbfbfeda0) 1729 rpc.rstatd RET ioctl 0 1729 rpc.rstatd CALL close(0x32) 1729 rpc.rstatd RET close 0 1729 rpc.rstatd CALL gettimeofday(0xbfbff178,0) 1729 rpc.rstatd RET gettimeofday 0 1729 rpc.rstatd CALL getpid 1729 rpc.rstatd RET getpid 1729/0x6c1 1729 rpc.rstatd CALL socket(0x2,0x2,0x11) 1729 rpc.rstatd RET socket 50/0x32 1729 rpc.rstatd CALL getsockname(0x32,0xbfbff090,0xbfbff08c) 1729 rpc.rstatd RET getsockname 0 1729 rpc.rstatd CALL getsockopt(0x32,0,0x13,0xbfbff084,0xbfbff088) 1729 rpc.rstatd RET getsockopt 0 1729 rpc.rstatd CALL setsockopt(0x32,0,0x13,0xbfbff080,0x4) 1729 rpc.rstatd RET setsockopt 0 1729 rpc.rstatd CALL bind(0x32,0xbfbff090,0x10) 1729 rpc.rstatd RET bind 0 1729 rpc.rstatd CALL ioctl(0x32,FIONBIO,0xbfbff174) 1729 rpc.rstatd RET ioctl 0 1729 rpc.rstatd CALL sendto(0x32,0x806b1f8,0x38,0,0x806b008,0x10) 1729 rpc.rstatd GIO fd 50 wrote 56 bytes "\M^E+&m\0\0\0\0\0\0\0\^B\0\^A\M^F\240\0\0\0\^B\0\0\0\^B\0\0\0\0\0\0\0\ \0\0\0\0\0\0\0\0\0\0\^A\M^F¡\0\0\0\^A\0\0\0\0\0\0\0\0" 1729 rpc.rstatd RET sendto 56/0x38 1729 rpc.rstatd CALL gettimeofday(0xbfbff0c0,0) 1729 rpc.rstatd RET gettimeofday 0 1729 rpc.rstatd CALL select(0x33,0xbfbff130,0,0,0xbfbff0b8) 1729 rpc.rstatd RET select 1 1729 rpc.rstatd CALL recvfrom(0x32,0x806b068,0x190,0,0xbfbff120,0xbfbff09c) 1729 rpc.rstatd GIO fd 50 read 28 bytes "\M^E+&m\0\0\0\^A\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\^A" 1729 rpc.rstatd RET recvfrom 28/0x1c 1729 rpc.rstatd CALL close(0x32) 1729 rpc.rstatd RET close 0 1729 rpc.rstatd CALL close(0x32) 1729 rpc.rstatd RET close -1 errno 9 Bad file descriptor 1729 rpc.rstatd CALL sigprocmask(0x1,0x2805cec0,0xbfbff200) 1729 rpc.rstatd RET sigprocmask 0 1729 rpc.rstatd CALL sigprocmask(0x3,0x2805ced0,0) 1729 rpc.rstatd RET sigprocmask 0 1729 rpc.rstatd CALL exit(0) Is there anything else I can do to help fix this problem? CU, Sec -- Komme wieder State-Changed-From-To: open->feedback State-Changed-By: iedowse State-Changed-When: Sun Dec 1 05:20:31 PST 2002 State-Changed-Why: It looks like Alfred may have fixed this in revision 1.14.2.1 of rstat_proc.c. Can you confirm that this is fixed in 4.7-RELEASE or a -STABLE from after July 11, 2002? http://www.freebsd.org/cgi/query-pr.cgi?pr=30484 State-Changed-From-To: feedback->closed State-Changed-By: iedowse State-Changed-When: Fri Dec 6 20:51:56 PST 2002 State-Changed-Why: Mail to submitter bounces. http://www.freebsd.org/cgi/query-pr.cgi?pr=30484 >Unformatted: