Incorrect reporting with failure in running fs_hash.sh

[nishakm]

Describe the bug
If there is any failure in the script fs_hash.sh, the error message that gets reported is WARNING - report - Cannot retrieve full image metadata.

To Reproduce
Steps to reproduce the behavior:

1. Start with machine with no attr installed
2. Run tern report -i hello-world
3. See log - says WARNING - report - Cannot retrieve full image metadata

Error in terminal

$ tern -l report -i hello-world:latest                                                                                                                                                            
2019-05-13 08:10:53,500 - DEBUG - __main__ - Starting...                                                                                                                                                                               
2019-05-13 08:10:53,501 - DEBUG - report - Setting up...                                                                                                                                                                               
2019-05-13 08:10:53,502 - DEBUG - container - Checking if image "hello-world:latest" is available on disk...                                                                                                                           
2019-05-13 08:10:53,505 - DEBUG - container - Image "hello-world:latest" found                                                                                                                                                         
2019-05-13 08:10:53,515 - DEBUG - rootfs - Running command: sudo /home/nisha/terndev/lib/python3.7/site-packages/tern/tools/fs_hash.sh /home/nisha/terndev/tern/temp/cdccdf50922d90e847e097347de49119be0f17c18b4a2d98da9919fa5884479d/c
ontents                                                                                                                                                                                                                                
2019-05-13 08:10:53,548 - WARNING - report - Cannot retrieve full image metadata                                                                                                                                                       
2019-05-13 08:10:53,548 - DEBUG - report - Teardown...                                                                                                                                                                                 
2019-05-13 08:10:53,549 - DEBUG - rootfs - Running command: sudo rm -rf temp/mergedir                                                                                                                                                  
2019-05-13 08:10:53,559 - DEBUG - rootfs - Running command: sudo rm -rf temp/workdir                                                                                                                                                   
2019-05-13 08:10:53,582 - DEBUG - __main__ - Report completed.                                                                                                                                                                         
2019-05-13 08:10:53,583 - DEBUG - __main__ - Finished                                                                                                                                                                                  
(terndev) nisha@ubuntu:~/terndev/tern$ tern -l report -i debian:buster                                                                                                                                                                 
2019-05-13 08:11:05,745 - DEBUG - __main__ - Starting...                                                                                                                                                                               
2019-05-13 08:11:05,745 - DEBUG - report - Setting up...                                                                                                                                                                               
2019-05-13 08:11:05,746 - DEBUG - container - Checking if image "debian:buster" is available on disk...                                                                                                                                
2019-05-13 08:11:05,749 - DEBUG - container - Image "debian:buster" found                                                                                                                                                              
2019-05-13 08:11:08,209 - DEBUG - rootfs - Running command: sudo /home/nisha/terndev/lib/python3.7/site-packages/tern/tools/fs_hash.sh /home/nisha/terndev/tern/temp/62fa53694b29fbc60f7088f083057844e0f90f3bd5c9910086f91bac962980e0/c
ontents                                                                                                                                                                                                                                
2019-05-13 08:11:13,624 - WARNING - report - Cannot retrieve full image metadata                                                                                                                                                       
2019-05-13 08:11:13,625 - DEBUG - report - Teardown...                                                                                                                                                                                 
2019-05-13 08:11:13,626 - DEBUG - rootfs - Running command: sudo rm -rf temp/mergedir
2019-05-13 08:11:13,633 - DEBUG - rootfs - Running command: sudo rm -rf temp/workdir
2019-05-13 08:11:13,795 - DEBUG - __main__ - Report completed.
2019-05-13 08:11:13,796 - DEBUG - __main__ - Finished

Expected behavior

2019-05-13 08:10:53,548 - ERROR - report - Error in running script fs_hash.sh

Environment you are running Tern on
Enter all that apply

• Operating System: VMware Fusion VM running Ubuntu 18.04 LTS
• Python version: 3.7

[rnjudge]

@nishakm Could we log an error message in tern/utils/rootfs.py where we directly call fs_hash.sh? This would result in both an error and warning message, but I don't think they necessarily need to be mutually exclusive. I'm thinking something like this when I run Tern on a system without attr:

# tern -l report -i debian:buster
....
2019-07-11 10:39:10,353 - DEBUG - rootfs - Running command: sudo /home/rjudge/ternenv/lib/python3.6/site-packages/tern/tools/fs_hash.sh /home/rjudge/ternenv/tern/temp/cdccdf50922d90e847e097347de49119be0f17c18b4a2d98da9919fa5884479d/contents
2019-07-11 10:39:10,386 - ERROR - rootfs - Error in running script fs_hash.sh
2019-07-11 10:39:10,388 - WARNING - report - Cannot retrieve full image metadata
.......

Lastly, do you think it would it be helpful to put a hint to the user that the issue could be related to attr if fs_hash fails? If the script fails on Linux, it is often because attr is not installed. On a mac, fs_hash.sh fails to run due to there being no getfattr command which is used in the fs_hash.sh script (with similar reasoning on Windows, I imagine). Maybe something like this?

2019-07-11 16:25:04,358 - ERROR - rootfs - Error in fs_hash.sh output. Check that attr is installed in your Linux environment.

[nishakm]

@rnjudge Typically the root_command function in tern/utils/rootfs.py should report out what the actual failure is. So if there is no attr installed the script should error out with something like no such command or something like that. The root_command function should return a message with this command. I get the feeling it is not doing it. It would be awesome if you could test this part out first. It would save us a bunch of reporting headaches down the line.

[rnjudge]

root_command is properly raising CalledProcessError when fs_hash fails. I wonder if it's not capturing the error message because it is too big to print somehow or perhaps the wrong format. If I run tern -l report -i debian:buster -f on a system without attr there are 10,372 lines(!) of error message captured in the error byte object passed to output in this line:
raise subprocess.CalledProcessError(1, cmd=full_cmd, output=error)

If you print out the error object contents it looks something like this repeated for 347465 characters:

b'find: \xe2\x80\x98getfattr\xe2\x80\x99: No such file or directory\nfind: \xe2\x80\x98getfattr\xe2\x80\x99: No such file or directory\nfind: \xe2\x80\x98getfattr\xe2\x80\x99: No such file or directory\nfind: \xe2\x80\x98getfattr\xe2\x80\x99: No such file or directory\nfind: \xe2\x80\x98getfattr\xe2\x80\x99: No such file or directory\nfind: \xe2\x80\x98getfattr\xe2\x80\x99: No such file or directory\nfind: \xe2\x80\x98getfattr\xe2\x80\x99: No such file or directory\nfind: \xe2\x80\x98getfattr\xe2\x80\x99: No such file or directory\n

[rnjudge]

@nishakm I think the issue lies in passing error to output in this line in root_command():

raise subprocess.CalledProcessError(1, cmd=full_cmd, output=error)

According to the documentation about the subprocess.CalledProcessError exception:

output

    Output of the child process if this exception is raised by check_output(). Otherwise, None.

Since the exception is not raised by check_output(), the output defaults to None. If you make the following change to root_command to use subprocess.check_output(), the proper error message is printed to the console:

@@ -56,7 +56,8 @@ def root_command(command, *extra):
                              stderr=subprocess.PIPE)
     result, error = pipes.communicate()  # nosec
     if error:
-        raise subprocess.CalledProcessError(1, cmd=full_cmd, output=error)
+        raise subprocess.CalledProcessError(
+            1, cmd=full_cmd, output=subprocess.check_output(full_cmd))

However, the issue now lies in trying to trim down the error message since running the above code yields 10k lines of error message:

2019-07-14 21:53:29,553 - DEBUG - rootfs - Running command:
 sudo /home/rjudge/ternenv/lib/python3.6/site-packages/tern/tools/fs_hash.sh /home/rjudge/ternenv/tern/temp
/0f28619fe69181d3af529d56692f1362b7a7c8a6bf8dc9ab0d6d4f9ef9b0004d/contents
find: ‘getfattr’: No such file or directory
find: ‘getfattr’: No such file or directory
find: ‘getfattr’: No such file or directory
find: ‘getfattr’: No such file or directory
find: ‘getfattr’: No such file or directory
find: ‘getfattr’: No such file or directory
find: ‘getfattr’: No such file or directory
<snip>

[nishakm]

@rnjudge from your findings on the fs_hash.sh output, I think a better shell script that will fail gracefully is needed rather than trying to deal with the ridiculously long error message. My understanding is that CalledProcessError is the generic subprocess exception, but maybe I'm wrong here. We could raise a generic exception instead.

[rnjudge]

@nishakm If we want to require attr to be installed in order to run, what do you think about the following:

1. Change fs_hash.sh to output any error messages from running the script into an output file that the user can examine after the fact. This will also be helpful if there is ever a need to file a bug report.
2. If any errors are generated running the script, modify fs_hash.sh to exit gracefully with a shorter, more clear error message passed to stderr. This will allow for pipes.communicate() to log the error message and raise the exception in rootfs.py.

I think it is OK to keep the CalledProcessError as long as we change the output argument to be something informative. With my proposal above, the output would look something like this:

2019-07-22 16:51:56,105 - DEBUG - rootfs - Running command: 
sudo /home/rjudge/ternenv/lib/python3.6/site-packages/tern/tools/fs_hash.sh
 /home/rjudge/ternenv/tern/temp/0477746f96c55ac74d949a55a3280d3af6b22d8a90e4a57f80a
bcaa133b2efce/contents
2019-07-22 16:51:58,789 - ERROR - rootfs - Command failed with:
fs_hash.sh failed to run as expected. See fs_hash.log for details.
2019-07-22 16:52:06,083 - WARNING - report - Cannot retrieve full image metadata

This "failed to run as expected" error message is of course custom within fs_hash.sh in order to avoid spamming the terminal. Any other function call to root_command would show the raw output error of the subprocess command call. In this case, fs_hash.log would contain:

$:~/ternenv/tern$ cat fs_hash.log | head
find: ‘getfattr’: No such file or directory
find: ‘getfattr’: No such file or directory
find: ‘getfattr’: No such file or directory

NOTE: fs_hash.log would not be available to the user if fs_hash.sh runs successfully.