Add a lot of logs for NS creation process

These logs make NS creation process more visible and
allow to easyly debug problems in it.
Log to STDERR only for now to simplify code.

Signed-off-by: Kostiantyn Kostiuk <kkostiuk@redhat.com>

Author: kostyanf14

bin/ns_unshared

@@ -16,6 +16,7 @@ module AutoHCK
       '/proc/sys/net/bridge/bridge-nf-call-ip6tables',
       '/proc/sys/net/bridge/bridge-nf-call-iptables'
     ].each do |file|
+      $stderr.write "[ns_unshared] Writing '0' to #{file}\n"
       File.write file, '0'
     rescue Errno::ENOENT
       # br_netfilter is not loaded
@@ -50,6 +51,7 @@ module AutoHCK
       %w[ip link add br_debug type bridge],
       %w[ip link set br_debug up]
     ].each do |cmd|
+      $stderr.write "[ns_unshared] Running (wait spawn): #{cmd.join(' ')}\n"
       Process.wait spawn(*cmd, out: :err)
       raise $CHILD_STATUS.to_s unless $CHILD_STATUS.success?
     rescue StandardError

bin/nsd

@@ -33,8 +33,11 @@ module AutoHCK
     argv << File.join(__dir__, 'ns_unshared')
 
     e_read, e_write = IO.pipe
+    $stderr.write "[nsd] Running (e pipe): #{e_read.fileno} => #{e_write.fileno}\n"
     r_read, r_write = IO.pipe
+    $stderr.write "[nsd] Running (r pipe): #{r_read.fileno} => #{r_write.fileno}\n"
     parent = Process.pid.to_s
+    $stderr.write "[nsd] Parent PID: #{parent}\n"
 
     fork do
       e_write.close
@@ -60,19 +63,24 @@ module AutoHCK
         # Call newgidmap so that virtiofsd can use setgroups() to drop subgroups.
         # unshare command in util-linux 2.38 can call newgidmap by its own, but
         # unfortunately it is not available on some supported systems.
-        system 'newgidmap', parent, '0', Process.gid.to_s, '1',
-               subid_start, subid_start, subid_count, exception: true, out: :err
+        command = ['newgidmap', parent, '0', Process.gid.to_s, '1', subid_start, subid_start, subid_count]
+        $stderr.write "[nsd child] Running (system): #{command.join(' ')}\n"
+        system(*command, exception: true, out: :err)
       end
 
       e_read.close_on_exec = false
       r_write.close_on_exec = false
-      exec 'slirp4netns', '-e', e_read.fileno.to_s, '-r', r_write.fileno.to_s,
-           '-a', 'slirp.sock', parent, 'tap_host', out: :err
+
+      command = ['slirp4netns', '-e', e_read.fileno.to_s, '-r', r_write.fileno.to_s,
+                 '-a', 'slirp.sock', parent, 'tap_host']
+      $stderr.write "[nsd child] Running (exec): #{command.join(' ')}\n"
+      exec(*command, out: :err)
     end
 
     e_read.close
     r_write.close
 
+    $stderr.write "[nsd] Running (exec, 3 => #{e_write.fileno}, 4 => #{r_read.fileno}): #{argv.join(' ')}\n"
     exec(*argv, 3 => e_write, 4 => r_read)
   end
 end

lib/setupmanagers/qemuhck/ns.rb

@@ -18,8 +18,7 @@ def self.enter(workspace, chdir, *argv)
             pid = pid_file.acquire
             begin
               Thread.handle_interrupt Object => :immediate do
-                system(*nsenter_argv(pid, chdir), '--', *argv)
-                exit $CHILD_STATUS.exitstatus
+                nsenter(pid, chdir, *argv)
               end
             ensure
               begin
@@ -42,7 +41,14 @@ def self.nsenter_argv(pid, chdir)
         argv
       end
 
-      private_class_method :nsenter_argv
+      def self.nsenter(pid, chdir, *argv)
+        command = [*nsenter_argv(pid, chdir), '--', *argv]
+        $stderr.write "[ns.rb] Running (system): #{command.join(' ')}\n"
+        system(*command)
+        exit $CHILD_STATUS.exitstatus
+      end
+
+      private_class_method :nsenter_argv, :nsenter
     end
   end
 end

lib/setupmanagers/qemuhck/qemuhck.rb

@@ -204,6 +204,7 @@ def run_hck_client(scope, studio, name, run_opts)
     end
 
     def self.enter(workspace_path)
+      $stderr.write "[qemuhck.rb] Entering namespace: #{workspace_path}\n"
       Ns.enter workspace_path, Dir.pwd, 'bin/auto_hck', '-w',
                workspace_path, *ARGV
     end