Encryption - safe init => /var: filesystem full

[HolyK]

Hiao,

First the specifications:
FreeNAS-9.2.0-RELEASE-x64 (ab098f4)
6x3TB WD green connected to on-board SAS2 on X10SL7-F (da0-da5)
2x2TB WD RED (Mirrored), (ada0,ada1)
1x 8GB USB stick for system (da7)
1z 8GB USB stick for scripts (da6)

Now the issue:
28.12. 21:15
- created RAIDZ2 with encryption enabled AND "Initialize Safely" checked
- six dd processes spawned and writing of random trash on the disks started

Code:

[root@HolyNAS] /# ps -efuxww | grep dd
root  9290 66.9  0.0  9908  2548 ??  R    9:16PM 153:01.84 DJANGO_SETTINGS_MODULE=freenasUI.settings PATH=/sbin:/bin:/usr/sbin:/usr/bin PWD=/ HOME=/ RC_PID=23 dd if=/dev/random of=/dev/gptid/f64188b1-6ffc-11e3-8909-00259086c71a.eli bs=1m
root  9288 64.2  0.0  9908  2548 ??  R    9:16PM 152:53.69 DJANGO_SETTINGS_MODULE=freenasUI.settings PATH=/sbin:/bin:/usr/sbin:/usr/bin PWD=/ HOME=/ RC_PID=23 dd if=/dev/random of=/dev/gptid/f54c6d12-6ffc-11e3-8909-00259086c71a.eli bs=1m
root  9286 63.8  0.0  9908  2548 ??  R    9:16PM 153:03.54 DJANGO_SETTINGS_MODULE=freenasUI.settings PATH=/sbin:/bin:/usr/sbin:/usr/bin PWD=/ HOME=/ RC_PID=23 dd if=/dev/random of=/dev/gptid/f453b025-6ffc-11e3-8909-00259086c71a.eli bs=1m
root  9284 63.0  0.0  9908  2548 ??  R    9:16PM 152:55.02 DJANGO_SETTINGS_MODULE=freenasUI.settings PATH=/sbin:/bin:/usr/sbin:/usr/bin PWD=/ HOME=/ RC_PID=23 dd if=/dev/random of=/dev/gptid/f35c2829-6ffc-11e3-8909-00259086c71a.eli bs=1m
root  9292 62.8  0.0  9908  2548 ??  R    9:16PM 153:09.79 DJANGO_SETTINGS_MODULE=freenasUI.settings PATH=/sbin:/bin:/usr/sbin:/usr/bin PWD=/ HOME=/ RC_PID=23 dd if=/dev/random of=/dev/gptid/f73e6dff-6ffc-11e3-8909-00259086c71a.eli bs=1m
root  9282 61.8  0.0  9908  2548 ??  R    9:16PM 152:56.83 DJANGO_SETTINGS_MODULE=freenasUI.settings PATH=/sbin:/bin:/usr/sbin:/usr/bin PWD=/ HOME=/ RC_PID=23 dd if=/dev/random of=/dev/gptid/f2699e30-6ffc-11e3-8909-00259086c71a.eli bs=1m

- Each disk was utilizing approximately ~10MB/s write speed. So after small math (3*1024*1024/3600/10) the whole process should take approx 87 hours, so the END timestamp should be around 1.1. 13:00
- I've been checking the system time to time - last check 31.12. at 13:30

Code:

[root@HolyNAS] ~# ps -efuxww | grep dd
root  9290 58.7  0.0  9908  2548 ??  R    Sat09PM 2331:39.52 DJANGO_SETTINGS_MODULE=freenasUI.settings PATH=/sbin:/bin:/usr/sbin:/usr/bin PWD=/ HOME=/ RC_PID=23 dd if=/dev/random of=/dev/gptid/f64188b1-6ffc-11e3-8909-00259086c71a.eli bs=1m
root  9286 58.4  0.0  9908  2548 ??  R    Sat09PM 2332:09.98 DJANGO_SETTINGS_MODULE=freenasUI.settings PATH=/sbin:/bin:/usr/sbin:/usr/bin PWD=/ HOME=/ RC_PID=23 dd if=/dev/random of=/dev/gptid/f453b025-6ffc-11e3-8909-00259086c71a.eli bs=1m
root  9288 55.6  0.0  9908  2548 ??  R    Sat09PM 2329:48.50 DJANGO_SETTINGS_MODULE=freenasUI.settings PATH=/sbin:/bin:/usr/sbin:/usr/bin PWD=/ HOME=/ RC_PID=23 dd if=/dev/random of=/dev/gptid/f54c6d12-6ffc-11e3-8909-00259086c71a.eli bs=1m
root  9284 55.3  0.0  9908  2548 ??  R    Sat09PM 2330:37.57 DJANGO_SETTINGS_MODULE=freenasUI.settings PATH=/sbin:/bin:/usr/sbin:/usr/bin PWD=/ HOME=/ RC_PID=23 dd if=/dev/random of=/dev/gptid/f35c2829-6ffc-11e3-8909-00259086c71a.eli bs=1m
root  9282 54.2  0.0  9908  2548 ??  RL  Sat09PM 2329:43.58 DJANGO_SETTINGS_MODULE=freenasUI.settings PATH=/sbin:/bin:/usr/sbin:/usr/bin PWD=/ HOME=/ RC_PID=23 dd if=/dev/random of=/dev/gptid/f2699e30-6ffc-11e3-8909-00259086c71a.eli bs=1m
root  9292 53.8  0.0  9908  2548 ??  R    Sat09PM 2333:14.58 DJANGO_SETTINGS_MODULE=freenasUI.settings PATH=/sbin:/bin:/usr/sbin:/usr/bin PWD=/ HOME=/ RC_PID=23 dd if=/dev/random of=/dev/gptid/f73e6dff-6ffc-11e3-8909-00259086c71a.eli bs=1m

1.1.2014 at 4PM
- checked the system again, and no dd processes were runing anymore, so i suppose the safe init finished, but
- zpool is NOT visible under "View volumes"
- all six disks are still visible under "ZFS volume manager" so they are acting like "available"
- But when checking via zpool commands, i can see that the pool was created

Code:

[root@HolyNAS] /# zpool list st0rage
NAME      SIZE  ALLOC  FREE    CAP  DEDUP  HEALTH  ALTROOT
st0rage  16.2T  1.79M  16.2T    0%  1.00x  ONLINE  /mnt
 
[root@HolyNAS] /# zpool status st0rage
  pool: st0rage
state: ONLINE
  scan: none requested
config:
 
        NAME                                                STATE    READ WRITE CKSUM
        st0rage                                            ONLINE      0    0    0
          raidz2-0                                          ONLINE      0    0    0
            gptid/f2699e30-6ffc-11e3-8909-00259086c71a.eli  ONLINE      0    0    0
            gptid/f35c2829-6ffc-11e3-8909-00259086c71a.eli  ONLINE      0    0    0
            gptid/f453b025-6ffc-11e3-8909-00259086c71a.eli  ONLINE      0    0    0
            gptid/f54c6d12-6ffc-11e3-8909-00259086c71a.eli  ONLINE      0    0    0
            gptid/f64188b1-6ffc-11e3-8909-00259086c71a.eli  ONLINE      0    0    0
            gptid/f73e6dff-6ffc-11e3-8909-00259086c71a.eli  ONLINE      0    0    0
 
errors: No known data errors

- zpool history shows that the pool was created 1.1. at 3:05 AM which is like 10hours before the expected time

Code:

[root@HolyNAS] /mnt# zpool history st0rage
History for 'st0rage':
2014-01-01.03:05:42 zpool create -o cachefile=/data/zfs/zpool.cache -o failmode=continue -o autoexpand=on -O aclmode=passthrough -O aclinherit=passthrough -f -m /st0rage -o altroot=/mnt st0rage raidz2 /dev/gptid/f2699e30-6ffc-11e3-8909-00259086c71a.eli /dev/gptid/f35c2829-6ffc-11e3-8909-00259086c71a.eli /dev/gptid/f453b025-6ffc-11e3-8909-00259086c71a.eli /dev/gptid/f54c6d12-6ffc-11e3-8909-00259086c71a.eli /dev/gptid/f64188b1-6ffc-11e3-8909-00259086c71a.eli /dev/gptid/f73e6dff-6ffc-11e3-8909-00259086c71a.eli

- BUT database entry is missing for all of the devices ! Following two entries are related to another encrypted pool.

Code:

[root@HolyNAS] /# sqlite3 /data/freenas-v1.db "select * from storage_encrypteddisk;"
2|1|gptid/0f79f96b-3c09-11e3-b566-00259086c71a|10
2|2|gptid/0fff42cb-3c09-11e3-b566-00259086c71a|11

- I have following errors in the console and these occurred BEFORE the pool was created

Code:

Dec 31 01:00:08 HolyNAS kernel: pid 22198 (bsdtar), uid 0 inumber 27877 on /var: filesystem full
Dec 31 01:33:26 HolyNAS kernel: pid 9290 (dd), uid 0 inumber 9306 on /var: filesystem full
Dec 31 01:33:38 HolyNAS last message repeated 9 times
Dec 31 01:33:39 HolyNAS kernel: pid 9282 (dd), uid 0 inumber 9302 on /var: filesystem full
Dec 31 01:33:40 HolyNAS kernel: pid 9282 (dd), uid 0 inumber 9302 on /var: filesystem full
Dec 31 01:33:41 HolyNAS kernel: pid 9286 (dd), uid 0 inumber 9304 on /var: filesystem full
Dec 31 01:33:42 HolyNAS kernel: pid 9290 (dd), uid 0 inumber 9306 on /var: filesystem full
Dec 31 01:33:44 HolyNAS kernel: pid 9282 (dd), uid 0 inumber 9302 on /var: filesystem full
Dec 31 01:33:45 HolyNAS kernel: pid 9282 (dd), uid 0 inumber 9302 on /var: filesystem full
Dec 31 01:33:46 HolyNAS kernel: pid 9292 (dd), uid 0 inumber 9307 on /var: filesystem full
Dec 31 01:33:47 HolyNAS kernel: pid 9292 (dd), uid 0 inumber 9307 on /var: filesystem full
Dec 31 01:33:48 HolyNAS kernel: pid 9284 (dd), uid 0 inumber 9303 on /var: filesystem full
Dec 31 01:33:50 HolyNAS kernel: pid 9290 (dd), uid 0 inumber 9306 on /var: filesystem full
Dec 31 01:33:51 HolyNAS kernel: pid 9286 (dd), uid 0 inumber 9304 on /var: filesystem full
Dec 31 01:33:53 HolyNAS last message repeated 2 times
Dec 31 01:33:54 HolyNAS kernel: pid 9288 (dd), uid 0 inumber 9305 on /var: filesystem full
Dec 31 01:33:56 HolyNAS last message repeated 2 times
Dec 31 01:33:57 HolyNAS kernel: pid 9290 (dd), uid 0 inumber 9306 on /var: filesystem full
Dec 31 01:34:00 HolyNAS last message repeated 3 times
Dec 31 01:34:01 HolyNAS kernel: pid 9286 (dd), uid 0 inumber 9304 on /var: filesystem full
Dec 31 01:34:02 HolyNAS kernel: pid 9288 (dd), uid 0 inumber 9305 on /var: filesystem full
Dec 31 01:34:03 HolyNAS kernel: pid 9286 (dd), uid 0 inumber 9304 on /var: filesystem full
Dec 31 01:34:04 HolyNAS kernel: pid 9286 (dd), uid 0 inumber 9304 on /var: filesystem full
Dec 31 01:34:06 HolyNAS kernel: pid 9284 (dd), uid 0 inumber 9303 on /var: filesystem full
Dec 31 01:34:08 HolyNAS last message repeated 2 times
Dec 31 01:34:09 HolyNAS kernel: pid 9282 (dd), uid 0 inumber 9302 on /var: filesystem full
Dec 31 01:34:10 HolyNAS kernel: pid 9290 (dd), uid 0 inumber 9306 on /var: filesystem full
Dec 31 01:34:15 HolyNAS last message repeated 5 times
Dec 31 01:34:17 HolyNAS kernel: pid 9284 (dd), uid 0 inumber 9303 on /var: filesystem full
Dec 31 01:34:18 HolyNAS kernel: pid 9286 (dd), uid 0 inumber 9304 on /var: filesystem full
Dec 31 01:34:19 HolyNAS kernel: pid 9292 (dd), uid 0 inumber 9307 on /var: filesystem full
Dec 31 01:34:20 HolyNAS kernel: pid 9284 (dd), uid 0 inumber 9303 on /var: filesystem full
Dec 31 01:34:22 HolyNAS kernel: pid 9290 (dd), uid 0 inumber 9306 on /var: filesystem full
Dec 31 01:34:23 HolyNAS kernel: pid 9282 (dd), uid 0 inumber 9302 on /var: filesystem full
Dec 31 01:34:24 HolyNAS kernel: pid 9282 (dd), uid 0 inumber 9302 on /var: filesystem full
Dec 31 01:34:25 HolyNAS kernel: pid 9286 (dd), uid 0 inumber 9304 on /var: filesystem full
Dec 31 01:34:26 HolyNAS kernel: pid 9284 (dd), uid 0 inumber 9303 on /var: filesystem full
Dec 31 01:34:28 HolyNAS kernel: pid 9290 (dd), uid 0 inumber 9306 on /var: filesystem full
Dec 31 01:34:29 HolyNAS kernel: pid 9290 (dd), uid 0 inumber 9306 on /var: filesystem full
Dec 31 01:34:30 HolyNAS kernel: pid 9292 (dd), uid 0 inumber 9307 on /var: filesystem full

- Bellow are details about what eating the whole space

Code:

[root@HolyNAS] /# cd /var
[root@HolyNAS] /var# df -h .
Filesystem Size Used Avail Capacity Mounted on
/dev/md2 149M 149M -11M 109% /var
[root@HolyNAS] /var# du -sm ./*
1 ./account
1 ./agentx
1 ./at
1 ./audit
1 ./authpf
1 ./backups
1 ./cache
1 ./crash
1 ./cron
29 ./db
1 ./empty
1 ./etc
1 ./games
1 ./heimdal
1 ./log
1 ./mail
1 ./md_size
1 ./msgs
1 ./named
1 ./netatalk
1 ./pbi
1 ./preserve
1 ./run
1 ./rwho
1 ./spool
120 ./tmp
1 ./yp
[root@HolyNAS] /var# ll | grep tmp
drwxrwxrwt 9 root wheel 1024 Jan 1 16:15 tmp/
[root@HolyNAS] /var# cd tmp
[root@HolyNAS] /var/tmp# du -sm ./*
1 ./alert
1 ./firmware
1 ./freenas_config.md5
1 ./ixdiagnose_boot.log
1 ./nginx
1 ./pbi-repo.rpo
1 ./rc.conf.freenas
1 ./sessionidw9yid6zrn9cas8jhff9a79ygq1w3bo59
0 ./tmp.P97hLF
20 ./tmp9n_LDV
20 ./tmpLul75M
20 ./tmpMU2IEc
20 ./tmpln2aD7
20 ./tmpoR6qmA
20 ./tmpvhQIxZ
1 ./vi.recover
[root@HolyNAS] /var/tmp# ll
total 121960
drwxrwxrwt 9 root wheel 1024 Jan 1 16:15 ./
drwxr-xr-x 29 root wheel 512 Dec 28 20:18 ../
drwxr-xr-x 2 root wheel 512 Dec 29 03:49 .PBI.22041/
drwxr-xr-x 2 root wheel 512 Dec 29 03:50 .PBI.23980/
drwxr-xr-x 2 root wheel 512 Jan 1 03:50 .PBI.25815/
drwxr-xr-x 2 root wheel 512 Dec 28 20:18 .PBI.3051/
-rw-r--r-- 1 root wheel 161 Jan 1 16:15 alert
drwx------ 2 www wheel 512 Jan 1 15:32 firmware/
-rw-r--r-- 1 root wheel 33 Dec 28 20:18 freenas_config.md5
-rw-r--r-- 1 root wheel 1628 Dec 28 20:18 ixdiagnose_boot.log
drwxr-xr-x 6 root wheel 512 Dec 28 20:18 nginx/
-rw-r--r-- 1 root wheel 945 Dec 20 16:57 pbi-repo.rpo
-rw-r--r-- 1 root wheel 741 Dec 28 20:18 rc.conf.freenas
-rw------- 1 root wheel 1408 Jan 1 15:32 sessionidw9yid6zrn9cas8jhff9a79ygq1w3bo59
-rw------- 1 root wheel 0 Dec 28 20:18 tmp.P97hLF
-rw-r--r-- 1 root wheel 20770797 Jan 1 03:04 tmp9n_LDV
-rw-r--r-- 1 root wheel 20766716 Jan 1 02:59 tmpLul75M
-rw-r--r-- 1 root wheel 20766720 Jan 1 03:02 tmpMU2IEc
-rw-r--r-- 1 root wheel 20766702 Jan 1 02:56 tmpln2aD7
-rw-r--r-- 1 root wheel 20766696 Jan 1 03:05 tmpoR6qmA
-rw-r--r-- 1 root wheel 20766720 Jan 1 03:00 tmpvhQIxZ
drwxrwxrwt 2 root wheel 512 Dec 20 23:26 vi.recover/
[root@HolyNAS] /var/tmp#

So, i have several questions:
- What the hell happened ?
- How can i verify that the safe initialization finished successfully - all disks are full of some random trash? I suppose they are, but want to be sure
- What should i do with the full FS? Delete manually or reboot and let the system do some cleanup?
- How to fix that poll which is somehow missing in the GUI but physically exists? I did not created passphrase yet but i can see the .key file under "/data/geli". Anyway autoimport from GUI is NOT possible since step 3/3 will show blank dropdown menu for "Volume" so its no-go.

If this will be confirmed, i will open a ticket.

Thanks

HolyK


EDIT: More info about the system

gpart show:

Code:

[root@HolyNAS] /# gpart show
=>        34  3907029101  ada0  GPT  (1.8T)
          34          94        - free -  (47k)
        128    4194304    1  freebsd-swap  (2.0G)
    4194432  3902834696    2  freebsd-zfs  (1.8T)
  3907029128          7        - free -  (3.5k)
 
=>        34  3907029101  ada1  GPT  (1.8T)
          34          94        - free -  (47k)
        128    4194304    1  freebsd-swap  (2.0G)
    4194432  3902834696    2  freebsd-zfs  (1.8T)
  3907029128          7        - free -  (3.5k)
 
=>      34  15124925  da6  GPT  (7.2G)
        34  15124925    1  freebsd-ufs  (7.2G)
 
=>      63  15669185  da7  MBR  (7.5G)
        63  1930257    1  freebsd  (942M)
  1930320        63      - free -  (31k)
  1930383  1930257    2  freebsd  [active]  (942M)
  3860640      3024    3  freebsd  (1.5M)
  3863664    41328    4  freebsd  (20M)
  3904992  11764256      - free -  (5.6G)
 
=>      0  1930257  da7s1  BSD  (942M)
        0      16        - free -  (8.0k)
      16  1930241      1  !0  (942M)
 
=>      0  1930257  da7s2  BSD  (942M)
        0      16        - free -  (8.0k)
      16  1930241      1  !0  (942M)
 
=>        34  5860533101  da0  GPT  (2.7T)
          34          94      - free -  (47k)
        128    4194304    1  freebsd-swap  (2.0G)
    4194432  5856338696    2  freebsd-zfs  (2.7T)
  5860533128          7      - free -  (3.5k)
 
=>        34  5860533101  da1  GPT  (2.7T)
          34          94      - free -  (47k)
        128    4194304    1  freebsd-swap  (2.0G)
    4194432  5856338696    2  freebsd-zfs  (2.7T)
  5860533128          7      - free -  (3.5k)
 
=>        34  5860533101  da2  GPT  (2.7T)
          34          94      - free -  (47k)
        128    4194304    1  freebsd-swap  (2.0G)
    4194432  5856338696    2  freebsd-zfs  (2.7T)
  5860533128          7      - free -  (3.5k)
 
=>        34  5860533101  da3  GPT  (2.7T)
          34          94      - free -  (47k)
        128    4194304    1  freebsd-swap  (2.0G)
    4194432  5856338696    2  freebsd-zfs  (2.7T)
  5860533128          7      - free -  (3.5k)
 
=>        34  5860533101  da4  GPT  (2.7T)
          34          94      - free -  (47k)
        128    4194304    1  freebsd-swap  (2.0G)
    4194432  5856338696    2  freebsd-zfs  (2.7T)
  5860533128          7      - free -  (3.5k)
 
=>        34  5860533101  da5  GPT  (2.7T)
          34          94      - free -  (47k)
        128    4194304    1  freebsd-swap  (2.0G)
    4194432  5856338696    2  freebsd-zfs  (2.7T)
  5860533128          7      - free -  (3.5k)

glabel status:

Code:

[root@HolyNAS] # glabel status
                                      Name  Status  Components
gptid/0f79f96b-3c09-11e3-b566-00259086c71a    N/A  ada0p2
gptid/0fff42cb-3c09-11e3-b566-00259086c71a    N/A  ada1p2
                                  ufs/misc    N/A  da6p1
                            ufs/FreeNASs3    N/A  da7s3
                            ufs/FreeNASs4    N/A  da7s4
                    ufsid/521c684590455604    N/A  da7s1a
                            ufs/FreeNASs1a    N/A  da7s1a
                            ufs/FreeNASs2a    N/A  da7s2a
gptid/0f6cd34c-3c09-11e3-b566-00259086c71a    N/A  ada0p1
gptid/0fe5ee9c-3c09-11e3-b566-00259086c71a    N/A  ada1p1
gptid/f24e70ca-6ffc-11e3-8909-00259086c71a    N/A  da0p1
gptid/f2699e30-6ffc-11e3-8909-00259086c71a    N/A  da0p2
gptid/f3415fa0-6ffc-11e3-8909-00259086c71a    N/A  da1p1
gptid/f35c2829-6ffc-11e3-8909-00259086c71a    N/A  da1p2
gptid/f4381f04-6ffc-11e3-8909-00259086c71a    N/A  da2p1
gptid/f453b025-6ffc-11e3-8909-00259086c71a    N/A  da2p2
gptid/f5314250-6ffc-11e3-8909-00259086c71a    N/A  da3p1
gptid/f54c6d12-6ffc-11e3-8909-00259086c71a    N/A  da3p2
gptid/f627a9bc-6ffc-11e3-8909-00259086c71a    N/A  da4p1
gptid/f64188b1-6ffc-11e3-8909-00259086c71a    N/A  da4p2
gptid/f723fa33-6ffc-11e3-8909-00259086c71a    N/A  da5p1
gptid/f73e6dff-6ffc-11e3-8909-00259086c71a    N/A  da5p2

database records:

Code:

[root@HolyNAS] /# sqlite3 /data/freenas-v1.db
SQLite version 3.8.0.2 2013-09-03 17:11:13
Enter ".help" for instructions
Enter SQL statements terminated with a ";"
 
sqlite> select * from storage_disk;
Disabled|60|3000592982016|||{devicename}da0|1|0|Disabled|1|Auto||bay4|da||1|da0
Disabled|60|3000592982016|WD-WMCxxxxxxxxx||{serial}WD-WMCxxxxxxxxx|1|1|Disabled|4|Auto||bay3|da||1|da1
Disabled|60|3000592982016|WD-WMCxxxxxxxxx||{serial}WD-WMCxxxxxxxxx|1|2|Disabled|5|Auto||bay2|da||1|da2
Disabled|60|3000592982016|WD-WMCxxxxxxxxx||{serial}WD-WMCxxxxxxxxx|1|3|Disabled|6|Auto||bay1|da||1|da3
Disabled|60|3000592982016|WD-WMCxxxxxxxxx||{serial}WD-WMCxxxxxxxxx|1|4|Disabled|7|Auto||bay6|da||1|da4
Disabled|60|3000592982016|WD-WMCxxxxxxxxx||{serial}WD-WMCxxxxxxxxx|1|5|Disabled|8|Auto||bay5|da||1|da5
Disabled|Always On|7743995904|||{devicename}da6|1|6|Disabled|9|Auto||USB-scripts|da||1|da6
Disabled|60|2000398934016|WD-WMCxxxxxxxxx||{serial}WD-WMCxxxxxxxxx|1|0|Disabled|10|Auto||bay7|ada||1|ada0
Disabled|60|2000398934016|WD-WMCxxxxxxxxx||{serial}WD-WMCxxxxxxxxx|1|1|Disabled|11|Auto||bay8|ada||1|ada1
Disabled|Always On|8022654976|||{devicename}da7|1|7|Disabled|13|Auto|||da||0|da7
 
sqlite> select * from storage_encrypteddisk;
2|1|gptid/0f79f96b-3c09-11e3-b566-00259086c71a|10
2|2|gptid/0fff42cb-3c09-11e3-b566-00259086c71a|11

as you can see,

 

[Dusan]

- What the hell happened ?

Something failed :).
When I created my pools I did not bother with "initialize safely". I see only two benefits of that checkbox:

1. You want to get rid of old data on the drives. Using DBAN is probably faster anyway.
2. Filing the drives with random data prevents an attacker from guessing how much data was written to the disk.

I used new disks (so 1. doesn't apply) and I don't care much about 2. -- I only care about somebody not being able to read the data, I don't care that somebody is able to figure that the pool is half full.

The initialize safely functionality in FN is IMHO a bit of an hack (e.g. the progress bar currently fails after 10 hours [https://github.com/freenas/freenas/blob/master/nanobsd/Files/etc/ix.rc.d/ix-nginx#L189], ...). It uses the six (now huge in your case) tmp files to track the progress of the dds (one file per dd). Each of those files grows by about 100 bytes every second. If it runs for many hours it will fill the var filesystem, pipes will be broken, dds killed... Some other things probably broke too (as the result of full /var) and you got your inconsistent result.

- How can i verify that the safe initialization finished successfully - all disks are full of some random trash? I suppose they are, but want to be sure

I don't think you can reliably test that. I'm also pretty sure it did not fill the entire disk as when /var got full the dds died the next second when they were asked to write the current progress into the temp files. If you really care about filling the drives with random data I suggest you use DBAN.

- What should i do with the full FS? Delete manually or reboot and let the system do some cleanup?

Reboot is the easiest option. /var is a ramdisk so it will be recreated on reboot.

- How to fix that poll which is somehow missing in the GUI but physically exists? I did not created passphrase yet but i can see the .key file under "/data/geli". Anyway autoimport from GUI is NOT possible since step 3/3 will show blank dropdown menu for "Volume" so its no-go.

I can try to find an CLI solution, but as we are not trying to save data it may be easier for you to restore a recent config DB backup and create the pool again.

Btw, your post inspired this: https://bugs.freenas.org/issues/3804 So, initialize safely will hopefully work faster in 9.2.1. :)

 

[Neil Whitworth]

Btw, your post inspired this: https://bugs.freenas.org/issues/3804 So, initialize safely will hopefully work faster in 9.2.1. :)

Are you SURE that using /dev/zero is going to be safe? Is not each block encrypted independatly - with the same input would you not get the same output, and so not prevent an attacker from guessing how much data was written to the disk.

I don't know how FreeBSD/geli work specificaly, but using a fixed input MAY lead to security vunerabilities.

 

[Dusan]

Are you SURE that using /dev/zero is going to be safe? Is not each block encrypted independatly - with the same input would you not get the same output, and so not prevent an attacker from guessing how much data was written to the disk.

I'm sure. geli is not using plain AES, it's used in XTS mode, so even if you fill the entire drive with the same data, the encrypted sectors will be different. You get the same ciphertext only if you write the same plaintext into the same sector. If you write it into a different sector, the ciphertext will be different. See this document for good description of AES-XTS: http://grouper.ieee.org/groups/1619/email/pdf00086.pdf

 

[Neil Whitworth]

I'm sure. geli is not using plain AES, it's used in XTS mode, so even if you fill the entire drive with the same data, the encrypted sectors will be different. You get the same ciphertext only if you write the same plaintext into the same sector. If you write it into a different sector, the ciphertext will be different. See this document for good description of AES-XTS: http://grouper.ieee.org/groups/1619/email/pdf00086.pdf

Thanks, that looks like interesting reading.

 

[HolyK]

You're probably right with the whole "initialize safely". Disks were used before for unencrypted RAIDZ2 so even without safe-init it would be impossible to read some "old" data from single disk.

Regarding "dd" ... well the space issue started 31.12. at 1:33AM but all six dd's were still running when i checked last time which was 31.12. at 1:30PM, to 12 hours later it was still running ...

Anyway, the whole situation got a bit complicated after reboot....

After reboot there was no pool available, it was not even possible to auto-import. I was expecting this since there were missing entries in the "storage_encrypteddisk" table. So i've just re-created encrypted pool from GUI without safe init, new pool was created and new entires were saved in the table, but there is more ....

1] After the first attempt to create encrypted pool WITH safe-init my database had following entries in the tables (serials and unrelated records removed bellow):

[root@HolyNAS] /# sqlite3 /data/freenas-v1.db "select * from storage_disk;"
Disabled|60|3000592982016|||{devicename}da0|1|0|Disabled|1|Auto||bay4|da||1|da0
Disabled|60|3000592982016|WD-WMCxxxxxxxxx||{serial}WD-WMCxxxxxxxxx|1|1|Disabled|4|Auto||bay3|da||1|da1
Disabled|60|3000592982016|WD-WMCxxxxxxxxx||{serial}WD-WMCxxxxxxxxx|1|2|Disabled|5|Auto||bay2|da||1|da2
Disabled|60|3000592982016|WD-WMCxxxxxxxxx||{serial}WD-WMCxxxxxxxxx|1|3|Disabled|6|Auto||bay1|da||1|da3
Disabled|60|3000592982016|WD-WMCxxxxxxxxx||{serial}WD-WMCxxxxxxxxx|1|4|Disabled|7|Auto||bay6|da||1|da4
Disabled|60|3000592982016|WD-WMCxxxxxxxxx||{serial}WD-WMCxxxxxxxxx|1|5|Disabled|8|Auto||bay5|da||1|da5

[root@HolyNAS] /# sqlite3 /data/freenas-v1.db "select * from storage_encrypteddisk;"
no records found

Note the first line - da0 was missing serial and "disk_identifier" was different from the rest. This is a known bug-#3761 which is already marked as resolved (Target version: 9.2.1-BETA)

2] After reboot and second attempt to create encrypted pool WITHOUT safe-init, i've ended up with working encrypted pool, i was able to create pass-phrase and recovery key. DB entries were modified and i had two da0 records.

[root@HolyNAS] ~# sqlite3 /data/freenas-v1.db "select * from storage_disk;"
Disabled|60|3000592982016|||{devicename}da0|1|0|Disabled|1|Auto||bay4|da||0|da0
Disabled|60|3000592982016|WD-WMCxxxxxxxxx||{serial}WD-WMCxxxxxxxxx|1|1|Disabled|4|Auto||bay3|da||1|da1
Disabled|60|3000592982016|WD-WMCxxxxxxxxx||{serial}WD-WMCxxxxxxxxx|1|2|Disabled|5|Auto||bay2|da||1|da2
Disabled|60|3000592982016|WD-WMCxxxxxxxxx||{serial}WD-WMCxxxxxxxxx|1|3|Disabled|6|Auto||bay1|da||1|da3
Disabled|60|3000592982016|WD-WMCxxxxxxxxx||{serial}WD-WMCxxxxxxxxx|1|4|Disabled|7|Auto||bay6|da||1|da4
Disabled|60|3000592982016|WD-WMCxxxxxxxxx||{serial}WD-WMCxxxxxxxxx|1|5|Disabled|8|Auto||bay5|da||1|da5
Disabled|Always On|3000592982016|WD-WMCxxxxxxxxx||{serial}WD-WMCxxxxxxxxx|1|0|Disabled|14|Auto|||da||1|da0

[root@HolyNAS] ~# sqlite3 /data/freenas-v1.db "select * from storage_encrypteddisk;"
4|3|gptid/165b1cb6-7305-11e3-8b4d-00259086c71a|14
4|4|gptid/17501067-7305-11e3-8b4d-00259086c71a|4
4|5|gptid/184e2c5e-7305-11e3-8b4d-00259086c71a|5
4|6|gptid/1954b2d7-7305-11e3-8b4d-00259086c71a|6
4|7|gptid/1a4c5e9d-7305-11e3-8b4d-00259086c71a|7
4|8|gptid/1b484480-7305-11e3-8b4d-00259086c71a|8

Note that the first encrypted disk entry is pointing to the newly created entry with id "14"

3] I rebooted again just to see where this is going and again something changed . The latest entry for da0 was not here anymore so the entry in storage_encrypteddisk was pointing to nonexisting disk.

[root@HolyNAS] ~# sqlite3 /data/freenas-v1.db "select * from storage_disk;"
Disabled|60|3000592982016|||{devicename}da0|1|0|Disabled|1|Auto||bay4|da||0|da0
Disabled|60|3000592982016|WD-WMCxxxxxxxxx||{serial}WD-WMCxxxxxxxxx|1|1|Disabled|4|Auto||bay3|da||1|da1
Disabled|60|3000592982016|WD-WMCxxxxxxxxx||{serial}WD-WMCxxxxxxxxx|1|2|Disabled|5|Auto||bay2|da||1|da2
Disabled|60|3000592982016|WD-WMCxxxxxxxxx||{serial}WD-WMCxxxxxxxxx|1|3|Disabled|6|Auto||bay1|da||1|da3
Disabled|60|3000592982016|WD-WMCxxxxxxxxx||{serial}WD-WMCxxxxxxxxx|1|4|Disabled|7|Auto||bay6|da||1|da4
Disabled|60|3000592982016|WD-WMCxxxxxxxxx||{serial}WD-WMCxxxxxxxxx|1|5|Disabled|8|Auto||bay5|da||1|da5

[root@HolyNAS] ~# sqlite3 /data/freenas-v1.db "select * from storage_encrypteddisk;"
4|3|gptid/165b1cb6-7305-11e3-8b4d-00259086c71a|
4|4|gptid/17501067-7305-11e3-8b4d-00259086c71a|4
4|5|gptid/184e2c5e-7305-11e3-8b4d-00259086c71a|5
4|6|gptid/1954b2d7-7305-11e3-8b4d-00259086c71a|6
4|7|gptid/1a4c5e9d-7305-11e3-8b4d-00259086c71a|7
4|8|gptid/1b484480-7305-11e3-8b4d-00259086c71a|8

Note that the first entry is now completely missing value for "encrypted_disk_id" column

4] So i manually fixed the wrong DB entries

[root@HolyNAS] ~# sqlite3 /data/freenas-v1.db
sqlite> update storage_disk set disk_serial='WD-WMCyyyyyyyyy' where disk_name='da0';
sqlite> update storage_disk set disk_identifier="{serial}WD-WMCyyyyyyyyy" where disk_name='da0';
sqlite> select * from storage_disk;
Disabled|60|3000592982016|WD-WMCyyyyyyyyy||{serial}WD-WMCyyyyyyyyy|1|0|Disabled|1|Auto||bay4|da||1|da0
Disabled|60|3000592982016|WD-WMCxxxxxxxxx||{serial}WD-WMCxxxxxxxxx|1|1|Disabled|4|Auto||bay3|da||1|da1
Disabled|60|3000592982016|WD-WMCxxxxxxxxx||{serial}WD-WMCxxxxxxxxx|1|2|Disabled|5|Auto||bay2|da||1|da2
Disabled|60|3000592982016|WD-WMCxxxxxxxxx||{serial}WD-WMCxxxxxxxxx|1|3|Disabled|6|Auto||bay1|da||1|da3
Disabled|60|3000592982016|WD-WMCxxxxxxxxx||{serial}WD-WMCxxxxxxxxx|1|4|Disabled|7|Auto||bay6|da||1|da4
Disabled|60|3000592982016|WD-WMCxxxxxxxxx||{serial}WD-WMCxxxxxxxxx|1|5|Disabled|8|Auto||bay5|da||1|da5

sqlite> update storage_encrypteddisk set encrypted_disk_id='1' where id='3';
sqlite> select * from storage_encrypteddisk;
4|3|gptid/165b1cb6-7305-11e3-8b4d-00259086c71a|1
4|4|gptid/17501067-7305-11e3-8b4d-00259086c71a|4
4|5|gptid/184e2c5e-7305-11e3-8b4d-00259086c71a|5
4|6|gptid/1954b2d7-7305-11e3-8b4d-00259086c71a|6
4|7|gptid/1a4c5e9d-7305-11e3-8b4d-00259086c71a|7
4|8|gptid/1b484480-7305-11e3-8b4d-00259086c71a|8

5] And then destroyed the pool from GUI, restarted and again created NEW encrypted pool to see the result. Finally everything went well and all records are as they should be (i hope).

[root@HolyNAS] ~# sqlite3 /data/freenas-v1.db "select * from storage_disk;"
Disabled|60|3000592982016|WD-WMCxxxxxxxxx||{serial}WD-WMCxxxxxxxxx|1|0|Disabled|1|Auto||bay4|da||1|da0
Disabled|60|3000592982016|WD-WMCxxxxxxxxx||{serial}WD-WMCxxxxxxxxx|1|1|Disabled|4|Auto||bay3|da||1|da1
Disabled|60|3000592982016|WD-WMCxxxxxxxxx||{serial}WD-WMCxxxxxxxxx|1|2|Disabled|5|Auto||bay2|da||1|da2
Disabled|60|3000592982016|WD-WMCxxxxxxxxx||{serial}WD-WMCxxxxxxxxx|1|3|Disabled|6|Auto||bay1|da||1|da3
Disabled|60|3000592982016|WD-WMCxxxxxxxxx||{serial}WD-WMCxxxxxxxxx|1|4|Disabled|7|Auto||bay6|da||1|da4
Disabled|60|3000592982016|WD-WMCxxxxxxxxx||{serial}WD-WMCxxxxxxxxx|1|5|Disabled|8|Auto||bay5|da||1|da5

[root@HolyNAS] ~# sqlite3 /data/freenas-v1.db "select * from storage_encrypteddisk;"
4|3|gptid/9649a21d-730a-11e3-b7d1-00259086c71a|1
4|4|gptid/96e29dce-730a-11e3-b7d1-00259086c71a|4
4|5|gptid/977f641a-730a-11e3-b7d1-00259086c71a|5
4|6|gptid/98168a8d-730a-11e3-b7d1-00259086c71a|6
4|7|gptid/98aecf8c-730a-11e3-b7d1-00259086c71a|7
4|8|gptid/9947d56e-730a-11e3-b7d1-00259086c71a|8

[root@HolyNAS] ~# sqlite3 /data/freenas-v1.db "select * from storage_volume;"
16931328633310814791|redmirror|c68e1744-89ac-43d2-9f9c-1a0e50561ddd|ZFS|2|2
18040412015978028445|st0rage|269e0f46-2442-40b1-a5b9-5f7cd018742b|ZFS|2|4

6] Passphrase and recovery key created, restarted three times and verified that both passphrase and recovery key is working properly.


So, should i open a ticket for this behavior so someone will take a look on it or not? :]

HolyK

 

[cyberjock]

I'm not sure if I like this /dev/zero thing. The whole reason why random stuff was written is because if you read a disk and can separate out what is data from what is not(which is possible if you fill the drive with /dev/zero there is a possibility you could use statistical analysis to help decrease the number of possible keys.

If you look at tools like Truecrypt it gives the option for writing random stuff to the drive too. It even recommends against using on SSDs because SSDs will TRIM the old data out and anyone that examines an SSD will always see the real data and no random data on the drive.

I think that if we are going to use /dev/zero we should change the GUI to say something like "Zero the disk". And once we go to that step we're now on a slippery slope because why not just offer to zero all disks when creating all pools? And if we're going to go to that extent, why not just offer to choose between a quick wipe or full wipe of zeros when creating a pool?

The whole purpose for using /dev/random was for security(makes the data and random data indistinguishable). /dev/zero can't provide that security, so choosing to write zeros isn't the answer. I think the answer is to offer /dev/random(and fix it so that /dev/random plays better) or get rid of the option entirely and make a comment in the GUI and manual that "proper security measures call for filling the drive with random bits before using it for encryption and that it is up to the user to perform this write before creating a pool on the drive".

 

[warri]

If I followed Dusan correctly, the zeros are just fed into the encryption layer which uses AES-XTS to generate ciphertext, which then is written to the physical disk. Even with an input of zeros, this resulting ciphertext has the property of being indistinguishable from random data.
Or shorter: The zeros aren't directly written to the disk, but going through geli first.

Correct me if I stand wrong - but otherwise the change would not make any sense indeed.

EDIT:
Note to the code change in the pull request: You didn't update the comment for random_wipe, since it's using /dev/null instead of /dev/random now. Also the name RandomWorker is now a bit misleading, because it only holds for encrypted devices? Just some thoughts for the responsible dev..

 

[Dusan]

Note to self: do not commit late in night. I realized a problem with the approach in the morning -- if an attacker is able to image the drive right after initialization it gives him lot of material for a potential known-plaintext key recovery attack (note, no such attack is known at this time). Xin independently pointed out the same in the bug ticket (and reverted the change). The solution to this is to first initialize the encryption with a random key, fill the drive with zeros (via the encryption), discard the temporary key and initialize the encryption again with the final key. @cyberjock, this is actually exactly what TrueCrypt does -- if you want to check it yourself the code is in Common\Format.c, function FormatNoFs, the interesting part starts around line 706 -- they memset a block of memory to zeros, then generate a random key and write that zero-filled sector to the entire disk (via encryption).
When you do this the attacker doesn't get any material for key recovery attacks (you discarded the key) and he still needs to break AES to distinguish "empty" space from data. It is just an different kind of "break". To read the data he needs to find a key-recovery or plaintext-recovery attack, for this you "only" need a know-plaintext distinguishing attack (no such attack is known at this time; however there is a known-key distinguishing attack against round-reduced AES, but as the attacker has to know the key the attack is only interesting in AES based hash functions).
We discussed this with Xin on IRC and for this moment the code will stay without change (i.e. slow) as there probably will be a geli improvement that will optionally initialize the disks in background.

 

[cyberjock]

If the zeros aren't being written directly then my whole comment is mute. I haven't checked out the code since I'm on my phone. :(

 

[HolyK]

Report #4088 raised