Error after going to release 8.20

[drjenk]

Hi,
I've been using the betas for a few months after buying hardware earlier this year, was able to do the gui updates for the past couple of betas (3 and 4 I believe). All was running smoothly. Then I noticed there was a final release. All appeared to be running smoothly as well. But after a couple days, I try to access the we interface and I get a large page of errors with this header:

Request Method: POST
Request URL: http://192.168.0.103/account/login/
Software Version: FreeNAS-8.2.0-RELEASE-p1-x64 (r11950)
Exception Type: OSError
Exception Value:

[Errno 28] No space left on device: '/tmp/sessionidc4611dac549e1c6ee2dca2e2351066a9'

Exception Location: /usr/local/lib/python2.7/site-packages/django/contrib/sessions/backends/file.py in save, line 90
Server time: Wed, 5 Sep 2012 20:58:52 -0700

I have the OS loaded on a compact flash card, 4gb. I do notice the "no space left on device". I guess the OS size has increased? I can still access the data however through my windows box, so the server is still running, I just cannot access the web page.
Incidentally, I did very soon after installing the OS run through the procedure on making the plugin jail, and installing miniDLNA, which appeared successful.
The workaround now is to reboot the box to access the web page, then I can access it for a day or two, then not. Any ideas?

Thanks
David J.

 

[ben]

The image size has not changed, 4GB should still be enough. Can you look at the console footer or use the shell command 'tail /var/log/messages' and see if something is spamming a lot?

 

[drjenk]

The image size has not changed, 4GB should still be enough. Can you look at the console footer or use the shell command 'tail /var/log/messages' and see if something is spamming a lot?

I established a putty connection using my user "david" account and entered that command, here is the output:

Sep 6 20:53:34 freenas kernel: pid 2051 (python), uid 0 inumber 21618 on /var: out of inodes
Sep 6 20:53:36 freenas kernel: pid 1675 (nmbd), uid 0 inumber 18542 on /var: out of inodes
Sep 6 20:53:38 freenas kernel: pid 2051 (python), uid 0 inumber 21618 on /var: out of inodes
Sep 6 20:53:43 freenas kernel: pid 2051 (python), uid 0 inumber 21618 on /var: out of inodes
Sep 6 20:53:46 freenas kernel: pid 1675 (nmbd), uid 0 inumber 18542 on /var: out of inodes
Sep 6 20:53:47 freenas kernel: pid 2051 (python), uid 0 inumber 21618 on /var: out of inodes
Sep 6 20:53:49 freenas kernel: pid 2147 (smbd), uid 0 inumber 37059 on /var: out of inodes
Sep 6 20:53:51 freenas kernel: pid 2051 (python), uid 0 inumber 21618 on /var: out of inodes
Sep 6 20:53:55 freenas kernel: pid 1666 (smbd), uid 0 inumber 37059 on /var: out of inodes
Sep 6 20:53:56 freenas kernel: pid 1675 (nmbd), uid 0 inumber 18542 on /var: out of inodes



Also, here is the "traceback" window output when I try to log into the web interface:

Environment:

Software Version: FreeNAS-8.2.0-RELEASE-p1-x64 (r11950)
Request Method: POST
Request URL: http://192.168.0.103/account/login/


Traceback:
File "/usr/local/lib/python2.7/site-packages/django/core/handlers/base.py" in get_response
111. response = callback(request, *callback_args, **callback_kwargs)
File "/usr/local/www/freenasUI/account/views.py" in login_wrapper
236. current_app=current_app, extra_context=extra_context)
File "/usr/local/lib/python2.7/site-packages/django/utils/decorators.py" in _wrapped_view
93. response = view_func(request, *args, **kwargs)
File "/usr/local/lib/python2.7/site-packages/django/views/decorators/cache.py" in _wrapped_view_func
79. response = view_func(request, *args, **kwargs)
File "/usr/local/lib/python2.7/site-packages/django/contrib/auth/views.py" in login
48. auth_login(request, form.get_user())
File "/usr/local/lib/python2.7/site-packages/django/contrib/auth/__init__.py" in login
80. request.session.cycle_key()
File "/usr/local/lib/python2.7/site-packages/django/contrib/sessions/backends/base.py" in cycle_key
271. self.create()
File "/usr/local/lib/python2.7/site-packages/django/contrib/sessions/backends/file.py" in create
70. self.save(must_create=True)
File "/usr/local/lib/python2.7/site-packages/django/contrib/sessions/backends/file.py" in save
90. fd = os.open(session_file_name, flags)

Exception Type: OSError at /account/login/
Exception Value: [Errno 28] No space left on device: '/tmp/sessionid9f868c50fdd464760cd8f8883e0e22e1'


And below that, here is the rest of the info below the traceback window:



Request information
GET

No GET data
POST
Variable Value
username u'admin'
csrfmiddlewaretoken u'7b84cdc54462b3244c4269e236a13f13'
password u'OIxyyFE0yH'
next u'/'
FILES

No FILES data
COOKIES
Variable Value
csrftoken '7b84cdc54462b3244c4269e236a13f13'
sessionid 'c18e8ec241f2642f310c501c6bf26755'
mytreeSaveStateCookie 'root%2C1%2C10%2C48%2C32%2C13%2C23%2C17%2C49%2C75%2C64%2C68%2C35%2C39%2C42%2C45%2C56%2C55'
fntreeSaveStateCookie 'root%2Croot%2F52%2Croot%2F52%2F59%2Croot%2F36%2Croot%2F36%2F42%2Croot%2F1%2F8%2Croot%2F75%2Croot%2F86%2Croot%2F86%2F118%2Croot%2F86%2F118%2F119%2Croot%2F86%2F118%2F119%2F120%2Croot%2F54%2F61%2Croot%2F54%2F61%2F62%2Croot%2F40%2Croot%2F56%2Croot%2F56%2F64%2Croot%2F56%2F64%2F65%2Croot%2F1%2F10%2Croot%2F87%2Croot%2F1%2Croot%2F88%2Croot%2F1%2F9%2Croot%2F1%2F5%2Croot%2F88%2F120%2F121%2F122%2Croot%2F88%2F120%2F121%2Croot%2F88%2F120'
META
Variable Value
wsgi.multiprocess False
HTTP_REFERER 'http://192.168.0.103/account/login/?next=/'
REDIRECT_STATUS '200'
SERVER_SOFTWARE 'nginx/1.0.11'
SCRIPT_NAME u''
REQUEST_METHOD 'POST'
PATH_INFO u'/account/login/'
SERVER_PROTOCOL 'HTTP/1.1'
QUERY_STRING ''
CONTENT_LENGTH '96'
HTTP_USER_AGENT 'Mozilla/5.0 (Windows NT 6.1; WOW64; rv:15.0) Gecko/20100101 Firefox/15.0'
HTTP_CONNECTION 'keep-alive'
HTTP_COOKIE 'csrftoken=7b84cdc54462b3244c4269e236a13f13; mytreeSaveStateCookie=root%2C1%2C10%2C48%2C32%2C13%2C23%2C17%2C49%2C75%2C64%2C68%2C35%2C39%2C42%2C45%2C56%2C55; fntreeSaveStateCookie=root%2Croot%2F52%2Croot%2F52%2F59%2Croot%2F36%2Croot%2F36%2F42%2Croot%2F1%2F8%2Croot%2F75%2Croot%2F86%2Croot%2F86%2F118%2Croot%2F86%2F118%2F119%2Croot%2F86%2F118%2F119%2F120%2Croot%2F54%2F61%2Croot%2F54%2F61%2F62%2Croot%2F40%2Croot%2F56%2Croot%2F56%2F64%2Croot%2F56%2F64%2F65%2Croot%2F1%2F10%2Croot%2F87%2Croot%2F1%2Croot%2F88%2Croot%2F1%2F9%2Croot%2F1%2F5%2Croot%2F88%2F120%2F121%2F122%2Croot%2F88%2F120%2F121%2Croot%2F88%2F120; sessionid=c18e8ec241f2642f310c501c6bf26755'
SERVER_NAME 'localhost'
REMOTE_PORT '62683'
wsgi.url_scheme 'http'
SERVER_PORT '80'
SERVER_ADDR '192.168.0.103'
DOCUMENT_ROOT '/usr/local/etc/nginx/html'
HTTP_CONTENT_LENGTH '96'
DOCUMENT_URI '/account/login/'
wsgi.input <flup.server.fcgi_base.InputStream object at 0x807e4ffd0>
HTTP_HOST '192.168.0.103'
wsgi.multithread True
HTTP_CONTENT_TYPE 'application/x-www-form-urlencoded'
REQUEST_URI '/account/login/'
HTTP_ACCEPT 'text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8'
wsgi.version (1, 0)
GATEWAY_INTERFACE 'CGI/1.1'
wsgi.run_once False
wsgi.errors <flup.server.fcgi_base.TeeOutputStream object at 0x808b3a950>
REMOTE_ADDR '192.168.0.11'
HTTP_ACCEPT_LANGUAGE 'en-us,en;q=0.5'
CONTENT_TYPE 'application/x-www-form-urlencoded'
CSRF_COOKIE '7b84cdc54462b3244c4269e236a13f13'
HTTP_ACCEPT_ENCODING 'gzip, deflate'

Thanks for any help. I'm leaving it in this state for now in case you need any more info. I can still access the data from both my windows PC and mythtv box, so the server is still running.

thanks

 

[ben]

Well, the diagnosis is that /var is full, and rebooting clears temporary files giving space again. Nothing in that dump suggests to me why /var is filling up so fast, though. Can you take a look at /var/log/messages while you're still able to log in and see what could be spamming it then? Also, what services do you have enabled, including any plugins or custom-installed software, and what cron jobs if any?

 

[drjenk]

Well, the diagnosis is that /var is full, and rebooting clears temporary files giving space again. Nothing in that dump suggests to me why /var is filling up so fast, though. Can you take a look at /var/log/messages while you're still able to log in and see what could be spamming it then? Also, what services do you have enabled, including any plugins or custom-installed software, and what cron jobs if any?

I am not sure what to look for, but I have attached a few of the message files to this thread. Also here is a dump of my var/log directory listing:

[david@freenas] /var/log> ls -la
total 4443
drwxr-xr-x 4 root wheel 1024 Sep 7 22:00 ./
drwxr-xr-x 26 root wheel 512 Sep 4 19:56 ../
-rw-r--r-- 1 root wheel 1 Sep 7 03:01 3ware_raid_alarms.today
-rw-r--r-- 1 root wheel 1 Sep 6 03:01 3ware_raid_alarms.yesterday
-rw------- 1 root wheel 1047 Sep 5 22:16 auth.log
-rw------- 1 root wheel 82947 Sep 7 23:17 cron
-rw------- 1 root wheel 3924 Sep 7 17:00 cron.0.bz2
-rw------- 1 root wheel 4084 Sep 7 09:00 cron.1.bz2
-rw------- 1 root wheel 119392 Sep 7 01:00 cron.2
-rw------- 1 root wheel 159234 Sep 6 16:00 cron.3
-rw------- 1 root wheel 28468 Sep 7 03:01 dmesg.today
-rw------- 1 root wheel 27400 Sep 6 03:01 dmesg.yesterday
-rw-r--r-- 1 root wheel 0 Sep 4 19:56 jail_software_console.log
-rw-r--r-- 1 root wheel 28028 Sep 5 22:16 lastlog
-rw-r--r-- 1 root wheel 63 Sep 4 19:59 lpd-errs
-rw-r----- 3 root wheel 241213 Sep 7 03:01 maillog
-rw-r----- 3 root wheel 241213 Sep 7 03:01 maillog.0
-rw-r----- 3 root wheel 241213 Sep 7 03:01 maillog.1
-rw-r----- 1 root wheel 533 Sep 5 00:00 maillog.2.bz2
-rw-r--r-- 1 root wheel 814 Sep 7 09:00 messages
-rw-r--r-- 1 root wheel 6042 Sep 7 03:00 messages.0.bz2
-rw-r--r-- 5 root wheel 645253 Sep 7 01:00 messages.1
-rw-r--r-- 5 root wheel 645253 Sep 7 01:00 messages.2
-rw-r--r-- 5 root wheel 645253 Sep 7 01:00 messages.3
-rw-r--r-- 5 root wheel 645253 Sep 7 01:00 messages.4
-rw-r--r-- 5 root wheel 645253 Sep 7 01:00 messages.5
-rw------- 1 root wheel 628 Sep 5 03:01 mount.today
-rw-r--r-- 1 www www 65891 Sep 7 23:16 nginx-access.log
-rw-r--r-- 1 www www 2722 Sep 7 22:00 nginx-access.log.0.bz2
-rw-r--r-- 1 www www 9193 Sep 7 20:00 nginx-access.log.1.bz2
-rw-r--r-- 1 www www 2201 Sep 5 20:57 nginx-error.log
-rw------- 1 root wheel 0 Sep 5 03:01 pf.today
-rw-r----- 1 root network 63 Sep 4 19:59 ppp.log
drwxr-xr-x 2 root wheel 512 Sep 4 19:56 proftpd/
drwxr-xr-x 3 root wheel 512 Sep 7 23:13 samba/
-rw------- 1 root wheel 63 Sep 4 19:59 security
-rw-r--r-- 1 root wheel 63 Sep 4 19:59 ups.log
-rw------- 1 root wheel 471 Jul 20 14:37 userlog
-rw-r--r-- 1 root wheel 120 Sep 5 22:16 wtmp
-rw------- 1 root wheel 199 Sep 4 19:56 xferlog

I have CIFS, FTP, plugins, S.M.A.R.T., SSH enabled. No I do not have any CRON jobs defined. Strange enough, without rebooting, this evening I'm now able to log in to the web page. So it appears to be intermittent.

 

[cyberjock]

The only thing I see from the logs besides log errors telling you the /var is full(duh??? an error to take up space because you are out of space... genius!) is:

Code:

Sep  7 00:55:02 freenas sudo:     root : TTY=unknown ; PWD=/root ; USER=root ; COMMAND=/etc/find_alias_for_smtplib.py -FCronDaemon -odi -oem -oi -t

I don't know what that is for. Perhaps someone can shed some light on it. It's part of FreeNAS but what it does I don't know.

 

[greco]

I had the problem as well with /var filling up:

Code:

Filesystem           1K-blocks       Used      Avail Capacity  Mounted on
/dev/md2                 152791    152628     -12060   109%    /var

Turned out to be /var/log/samba/log.nmbd taking up 128 MB:

[root@freenas] /var/log/samba# ls -alh

Code:

total 131721
drwxr-xr-x  3 root  wheel   512B Oct 26 09:49 ./
drwxr-xr-x  4 root  wheel   1.0K Oct 29 03:01 ../
drwx------  5 root  wheel   512B Oct 22 10:13 cores/
-rw-r--r--  1 root  wheel   128M Oct 29 19:03 log.nmbd
-rw-r--r--  1 root  wheel   4.5K Oct 29 19:02 log.smbd
-rw-r--r--  1 root  wheel    10K Oct 26 02:30 log.smbd.old
-rw-r--r--  1 root  wheel     0B Oct 22 10:13 log.wb-FREENAS
-rw-r--r--  1 root  wheel     0B Oct 22 10:13 log.wb-BUILTIN
-rw-r--r--  1 root  wheel   501B Oct 29 18:20 log.wb-DOMAIN
-rw-r--r--  1 root  wheel    13K Oct 26 08:49 log.wb-DOMAIN.old
-rw-r--r--  1 root  wheel   725B Oct 22 10:13 log.winbindd
-rw-r--r--  1 root  wheel     0B Oct 22 10:13 log.winbindd-dc-connect
-rw-r--r--  1 root  wheel   1.0K Oct 29 18:46 log.winbindd-idmap

The log is mostly this:

Code:

[2012/10/22 10:56:27,  0] nmbd/nmbd_packets.c:1515(process_nmb_request)
  process_nmb_request: Multihomed registration request must be directed at a WINS server.
[2012/10/22 10:56:27,  0] nmbd/nmbd_packets.c:1515(process_nmb_request)
  process_nmb_request: Multihomed registration request must be directed at a WINS server.
[2012/10/22 10:56:27,  0] nmbd/nmbd_packets.c:1515(process_nmb_request)
  process_nmb_request: Multihomed registration request must be directed at a WINS server.
[2012/10/22 10:56:31,  0] nmbd/nmbd_incomingrequests.c:213(process_name_registration_request)
  process_name_registration_request: unicast name registration request received for name DOMAIN<00> from IP 10.0.0.9 on subnet UNICAST_SUBNET. Error - should be sent to WINS server
[2012/10/22 10:56:31,  0] nmbd/nmbd_incomingrequests.c:213(process_name_registration_request)
  process_name_registration_request: unicast name registration request received for name DOMAIN<1e> from IP 10.0.0.9 on subnet UNICAST_SUBNET. Error - should be sent to WINS server
[2012/10/22 10:56:31,  0] nmbd/nmbd_incomingrequests.c:172(process_name_refresh_request)
  process_name_refresh_request: unicast name registration request received for name DOMAIN<1e> from IP 10.0.0.9 on subnet UNICAST_SUBNET.
[2012/10/22 10:56:31,  0] nmbd/nmbd_incomingrequests.c:173(process_name_refresh_request)
  Error - should be sent to WINS server
[2012/10/22 10:56:31,  0] nmbd/nmbd_incomingrequests.c:172(process_name_refresh_request)
  process_name_refresh_request: unicast name registration request received for name DOMAIN<00> from IP 10.0.0.9 on subnet UNICAST_SUBNET.
[2012/10/22 10:56:31,  0] nmbd/nmbd_incomingrequests.c:173(process_name_refresh_request)
  Error - should be sent to WINS server
[2012/10/22 10:56:31,  0] nmbd/nmbd_incomingrequests.c:172(process_name_refresh_request)
  process_name_refresh_request: unicast name registration request received for name FREENAS<00> from IP 10.0.0.9 on subnet UNICAST_SUBNET.
[2012/10/22 10:56:31,  0] nmbd/nmbd_incomingrequests.c:173(process_name_refresh_request)
  Error - should be sent to WINS server
[2012/10/22 10:56:33,  0] nmbd/nmbd_packets.c:1515(process_nmb_request)
  process_nmb_request: Multihomed registration request must be directed at a WINS server.
[2012/10/22 10:56:33,  0] nmbd/nmbd_packets.c:1515(process_nmb_request)
  process_nmb_request: Multihomed registration request must be directed at a WINS server.
[2012/10/22 10:56:33,  0] nmbd/nmbd_packets.c:1515(process_nmb_request)
  process_nmb_request: Multihomed registration request must be directed at a WINS server.
[2012/10/22 10:56:33,  0] nmbd/nmbd_incomingrequests.c:172(process_name_refresh_request)
  process_name_refresh_request: unicast name registration request received for name FREENAS<03> from IP 10.0.0.9 on subnet UNICAST_SUBNET.
[2012/10/22 10:56:33,  0] nmbd/nmbd_incomingrequests.c:173(process_name_refresh_request)
  Error - should be sent to WINS server
[2012/10/22 10:56:33,  0] nmbd/nmbd_incomingrequests.c:172(process_name_refresh_request)

10.0.0.9 is the freenas running cifs (obviously).

So I deleted that really big log file, but did not get any free space back. df still reports 109% utilization(!) for /var
Why would that be?
How can I free up space on /var without rebooting?
And how can I stop those error messages to prevent the excess log file?

uname -a
FreeBSD freenas 8.2-RELEASE-p9 FreeBSD 8.2-RELEASE-p9 #0: Thu Jul 19 12:39:10 PDT 2012 root@build.ixsystems.com:/build/home/jpaetzel/8.2.0/os-base/amd64/build/home/jpaetzel/8.2.0/FreeBSD/src/sys/FREENAS.amd64 amd64

Thanks!

 

[greco]

killed process nmbd and got my space back:

Code:

[root@freenas] /etc/rc.d# ps -aux | grep nmbd
root    2860  0.7  0.1 41516  6608  ??  Ss   22Oct12 105:58.52 /usr/local/sbin/nmbd
root    2180  0.0  0.0  8976  1344   0  R+    7:56PM   0:00.00 grep nmbd
[root@freenas] /etc/rc.d# kill 2860
[root@freenas] /etc/rc.d# df /var
Filesystem           1K-blocks       Used      Avail Capacity  Mounted on
/dev/md2                 152791     20923     119645    15%    /var

OH, and then I manually restarted it:

Code:

[root@freenas] /etc/rc.d#  /usr/local/sbin/nmbd
[root@freenas] /etc/rc.d# smbcontrol nmbd ping
PONG from pid 2193

(previously, the ping command timed out)

I'll be watching log.nmbd for log explosion, but my temp fix will probably be a cron job to delete that file and cycle the service.

 

[cyberjock]

I have a $1million question. These kinds of 'disk full' issues creep up from time to time. I know that the way FreeNAS is designed right now you need a true 2GB USB stick. Typically what is recommended is a 4GB stick since some 2GB sticks are 2GiB. So why not increase the partition size to 1.7GB. Since most of us are using a 4GB stick, it won't matter. Or is the issue more of trying to keep things the way they are for simplicity?

As another idea, why not make a FreeNAS installer that creates a 1.5GB partition and let users choose to use it if they wish. Once the USB drive is formatted and setup initially the partitions won't change. So you'd permanently have "oversized" partitions for a standard FreeNAS install.

Just throwing ideas out there...

 

[greco]

My system is installed to an 8GB stick, but I don't think more space is the answer because the first log entry was Oct 22 and the last log entry was Oct 27. So in 5 days it grew from 0 to 128 MB. Throwing more space at it will just make it take longer to fill up.

Rotating the log every day and auto removing old logs as space fills up would help a lot.
Also, how about some notification via e-mail. There are other e-mail notifications built into the system, I think if an e-mail was generated as /var hit 90% usage or whatever would be a tremendous help in at least having a chance to go in and fix things before the system fails.

Incidentally, ever since I killed and restarted nmbd, its log file has not grown at all.

 

[JaimieV]

So I deleted that really big log file, but did not get any free space back. df still reports 109% utilization(!) for /var

That's normal for Unix-like systems - if the file is still open when it is 'deleted', it's not really deleted until the process closes (as you worked out after). The "109%" is also normal, as some space is reserved for Root to use so that at least normal users can't fill up filesystems...