"Operation not permitted" on files over 2GB on ext4 filesystem

Question

I have a bit of a mystery. I have an Ubuntu 17.04 system (upgraded from 16.04 LTS) using ext4 as it's main filesystem. I used wget and curl to download a 2.3GB iso, but i cannot mount it. In fact, I cannot do any operation on it: md5sum, wc, cat, mount -o loop, etc... without getting an "operation not permitted". I can "rm" it, though. I am root, and the perms on the file are 644. I cannot do an "lsattr" nor "chattr" on it without "operation not permitted". I have proven that it's exactly related to the filesize as I did this: dd if=/dev/zero of=/tmp/test.iso bs=1M count=2047 and I am able to read test.iso as it's 1M less than 2G, but if i change it to 2048, I am unable to read the file. I understand that ext4 has a bare minimum limit of 16GB, but I am way under that. The files appear to be created just fine.

I did a thorough search before posting and nothing is related to my problem. No, it's not FAT. It's ext4. I see no errors in dmesg after accessing the file, as this would show apparmour errors. I doubt it's an immutable perm as I don't even have permission to lsattr on it. I have an almost identical Ubuntu 17.04 system and it works fine (except that was installed fresh instead of via upgrade from 16.04).

If I write to /dev/shm instead of /tmp, I can md5sum a 3GB file just fine... so there's something related to the way it's mounting /. /dev/shm is obviously a different mountpoint and not ext4.

# ls -l asm8.iso
-rw-r--r-- 1 root root 2253135872 Jan 15 20:27 asm8.iso

# md5sum asm8.iso
md5sum: asm8.iso: Operation not permitted

# strace -f md5sum asm8.iso
...
open("asm8.iso", O_RDONLY)              = -1 EPERM (Operation not permitted)
...

# lsattr asm8.iso
lsattr: Operation not permitted While reading flags on asm8.iso

# mount |grep " / "
/dev/mapper/asci--vg-root on / type ext4 (rw,relatime,errors=remount-ro,data=ordered)

# tune2fs -l /dev/mapper/asci--vg-root

...
Filesystem features:      has_journal ext_attr resize_inode dir_index filetype needs_recovery extent flex_bg sparse_super large_file huge_file uninit_bg dir_nlink extra_isize
Filesystem flags:         signed_directory_hash
Filesystem state:         clean
Filesystem OS type:       Linux
...

I compared the working system, and the only difference is that it doesnt have uninit_bg, and has 2 extras: 64bit,metadata_csum. I researched these flags and they don't seem to be relevant to the issue.

Does anyone have any ideas? If you want to see the output of any command, I will gladly share them. Thanks in advance.

Here is the extra info:

# df -h
Filesystem                 Size  Used Avail Use% Mounted on
udev                       7.9G     0  7.9G   0% /dev
tmpfs                      1.6G  114M  1.5G   8% /run
/dev/mapper/asci--vg-root  992G  643G  299G  69% /
tmpfs                      7.9G     0  7.9G   0% /dev/shm
tmpfs                      5.0M     0  5.0M   0% /run/lock
tmpfs                      7.9G     0  7.9G   0% /sys/fs/cgroup
/dev/sda1                  472M  116M  332M  26% /boot
tmpfs                      1.6G     0  1.6G   0% /run/user/999
tmpfs                      1.6G     0  1.6G   0% /run/user/1003
tmpfs                      1.6G     0  1.6G   0% /run/user/0
tmpfs                      1.6G     0  1.6G   0% /run/user/1008

 # df -i
Filesystem                  Inodes   IUsed    IFree IUse% Mounted on
udev                       2046118     419  2045699    1% /dev
tmpfs                      2051789     712  2051077    1% /run
/dev/mapper/asci--vg-root 66035712 3469883 62565829    6% /
tmpfs                      2051789       1  2051788    1% /dev/shm
tmpfs                      2051789       5  2051784    1% /run/lock
tmpfs                      2051789      16  2051773    1% /sys/fs/cgroup
/dev/sda1                   124928     315   124613    1% /boot
tmpfs                      2051789       5  2051784    1% /run/user/999
tmpfs                      2051789       5  2051784    1% /run/user/1003
tmpfs                      2051789       5  2051784    1% /run/user/0
tmpfs                      2051789       5  2051784    1% /run/user/1008

# cat /etc/fstab
# /etc/fstab: static file system information.
#
# Use 'blkid' to print the universally unique identifier for a
# device; this may be used with UUID= as a more robust way to name devices
# that works even if disks are added and removed. See fstab(5).
#
#                
/dev/mapper/asci--vg-root /               ext4    errors=remount-ro 0       1
# /boot was on /dev/sda1 during installation
UUID=20926db6-5e54-4907-912a-5fe996f45adc /boot           ext2    defaults        
0       2
/dev/mapper/asci--vg-swap_1 none            swap    sw              0       0
/dev/fd0        /media/floppy0  auto    rw,user,noauto,exec,utf8 0       0

It's not a directory issue as the files are created fine in the same directory: I can create the 2 files.

root@asci /tmp
# dd if=/dev/zero of=/tmp/file2047.iso bs=1M count=2047
2047+0 records in
2047+0 records out
2146435072 bytes (2.1 GB, 2.0 GiB) copied, 6.46013 s, 332 MB/s

root@asci /tmp
# dd if=/dev/zero of=/tmp/file2048.iso bs=1M count=2048
2048+0 records in
2048+0 records out
2147483648 bytes (2.1 GB, 2.0 GiB) copied, 60.2936 s, 35.6 MB/s

root@asci /tmp
# ls -ls /tmp/file*.iso
2096132 -rw-r--r-- 1 root root 2146435072 Jan 19 05:52 /tmp/file2047.iso
2097156 -rw-r--r-- 1 root root 2147483648 Jan 19 05:53 /tmp/file2048.iso

Even though md5sum, cat and wc all say "operation not permitted", it seems as though I can run file and stat on them:

# file *.iso
file2047.iso: data
file2048.iso: writable, regular file, no read permission

Here's stat. I don't see notable differences.

# stat *.iso
  File: file2047.iso
  Size: 2146435072      Blocks: 4192264    IO Block: 4096   regular file
Device: fd00h/64768d    Inode: 7380361     Links: 1
Access: (0644/-rw-r--r--)  Uid: (    0/    root)   Gid: (    0/    root)
Access: 2018-01-19 05:52:30.925760162 +0100
Modify: 2018-01-19 05:52:30.921760136 +0100
Change: 2018-01-19 05:52:30.921760136 +0100
 Birth: -
  File: file2048.iso
  Size: 2147483648      Blocks: 4194312    IO Block: 4096   regular file
Device: fd00h/64768d    Inode: 7380363     Links: 1
Access: (0644/-rw-r--r--)  Uid: (    0/    root)   Gid: (    0/    root)
Access: 2018-01-19 05:52:36.765797317 +0100
Modify: 2018-01-19 05:53:37.034180299 +0100
Change: 2018-01-19 05:53:37.034180299 +0100
 Birth: -

I'm not an apparmor expert, but rather than go through a learning curve, I just disabled it and you can see that it's still a problem. I suspected it wasn't the issue because I think that "dmesg" should report apparmor blocking messages and there was no new dmesg output during my tests.

# service apparmor stop

root@asci /tmp
# service apparmor teardown
 * Unloading AppArmor profiles
   ...done.

root@asci /tmp
# update-rc.d -f apparmor remove

root@asci /tmp
# wc -c file2048.iso
wc: file2048.iso: Operation not permitted

OMG. What finally fixed it was "apt remove apparmor; reboot". Now it works. So it must've been an apparmor profile. I don't use it, so something in the default apparmor settings is preventing the viewing of files over 2G. Does anyone have any idea what setting that might be? I will have to reinstall now to know.

Answer 1

I have solved my problem. The reason for not being able to access files over 2GB in size is due to my antivirus software (McAfee for Linux - Endpoint Security for Linux Threat Prevention). It was not due to apparmor, funky filesystem options, permissions, disk space or older filesystems.

Here is how I came to my conclusion. The troubleshooting steps might be interesting. Immediately following a reboot, I can quickly create a 2G file and probe it like so:

root@asci /tmp
# dd if=/dev/zero of=/tmp/file2049.iso bs=1M count=2049
2049+0 records in
2049+0 records out
2148532224 bytes (2.1 GB, 2.0 GiB) copied, 2.05888 s, 1.0 GB/s

root@asci /tmp
# md5sum file2049.iso
4555da35a7064cc499ba1e3f6fa1993a  file2049.iso

Within a minute, the md5sum no longer works.

To rule out crontabs, I disabled crontab, and also wrote a 1-liner script to output 0 upon successful read and 1 if unsuccessful. Notice that it breaks at the 40'th second (indicating most likely not a cron job):

# while [ 1 == 1 ]; do echo -n "`date` - ";dd if=asm8.iso bs=1M count=30 2>&1|grep -c "Operation not permi"; sleep 1;date >> /var/log/ps.log; ps -efww >> /var/log/ps.log; done
Fri Jan 19 18:57:28 CET 2018 - 0
Fri Jan 19 18:57:30 CET 2018 - 0
Fri Jan 19 18:57:31 CET 2018 - 0
Fri Jan 19 18:57:32 CET 2018 - 0
Fri Jan 19 18:57:33 CET 2018 - 0
Fri Jan 19 18:57:34 CET 2018 - 0
Fri Jan 19 18:57:35 CET 2018 - 0
Fri Jan 19 18:57:36 CET 2018 - 0
Fri Jan 19 18:57:37 CET 2018 - 0
Fri Jan 19 18:57:38 CET 2018 - 0
Fri Jan 19 18:57:39 CET 2018 - 0
Fri Jan 19 18:57:40 CET 2018 - 1
Fri Jan 19 18:57:41 CET 2018 - 1
Fri Jan 19 18:57:42 CET 2018 - 1
Fri Jan 19 18:57:43 CET 2018 - 1
Fri Jan 19 18:57:44 CET 2018 - 1

I only dd the start of the file, as that's all I need to test it, as it takes 48 seconds to read the entire thing. I logged the ps output to /var/log/ps.log. To do a diff on the ps output by comparing what changed between the 39th second and 40th second, I did this:

# cat ps.log |grep "Fri Jan 19 18:57:39 CET 2018" -A10000 |grep "Fri Jan 19 18:57:40 CET 2018" -B10000 > /tmp/ps39
# cat ps.log |grep "Fri Jan 19 18:57:40 CET 2018" -A10000 |grep "Fri Jan 19 18:57:41 CET 2018" -B10000 > /tmp/ps40
# cd /tmp

Comparing the ps outputs between the 39th and 40th second:

# diff ps39 ps40
 Fri Jan 19 18:57:40 CET 2018
266c266
 root      2412  1276 97 18:57 ?        00:00:19 /opt/isec/ens/threatprevention/bin/isectpd
275,276c275,278
 root      2632  2412  1 18:57 ?        00:00:00 /opt/isec/ens/threatprevention/bin/isectpd
> root      2635  2412 11 18:57 ?        00:00:00 /opt/isec/ens/threatprevention/bin/isectpd
> root      2663  2518  0 18:57 pts/1    00:00:00 ps -efww

So, that's it! Once the isectpd process started up at the 40th second, it disabled access to my 2GB file.

Once I did this:

# systemctl stop isectpd

It started working. Obviously, this is a bandaid until I find out how to allow > 2GB files from McAfee. If anyone has any experience with this, feel free to chime in.

Cheers.