Merge pull request #56 from smashwilson/36-logger

Logger

.gitignore

 config.yml
 tmp/*
+*.log

config.yml.example

@@ -26,3 +26,14 @@ redis:
   # socket: /tmp/redis.socket # Only define this if you want to use sockets
   namespace: resque:gitlab
 
+# Log file.
+# Default is gitlab-shell.log in the root directory.
+# log_file: "/home/git/gitlab-shell/gitlab-shell.log"
+
+# Log level. INFO by default
+log_level: INFO
+
+# Audit usernames.
+# Set to true to see real usernames in the logs instead of key ids, which is easier to follow, but
+# incurs an extra API call on every gitlab-shell command.
+audit_usernames: false

lib/gitlab_config.rb

@@ -31,6 +31,18 @@ class GitlabConfig
     redis['namespace'] || 'resque:gitlab'
   end
 
+  def log_file
+    @config['log_file'] ||= File.join(ROOT_PATH, 'gitlab-shell.log')
+  end
+
+  def log_level
+    @config['log_level'] ||= 'INFO'
+  end
+
+  def audit_usernames
+    @config['audit_usernames'] ||= false
+  end
+
   # Build redis command to write update event in gitlab queue
   def redis_command
     if redis.empty?

lib/gitlab_keys.rb

 require 'open3'
 
 require_relative 'gitlab_config'
+require_relative 'gitlab_logger'
 
 class GitlabKeys
   attr_accessor :auth_file, :key
@@ -17,6 +18,7 @@ class GitlabKeys
     when 'add-key'; add_key
     when 'rm-key';  rm_key
     else
+      $logger.warn "Attempt to execute invalid gitlab-keys command #{@command.inspect}."
       puts 'not allowed'
       false
     end
@@ -25,12 +27,14 @@ class GitlabKeys
   protected
 
   def add_key
+    $logger.info "Adding key #{@key_id} => #{@key.inspect}"
     cmd = "command=\"#{ROOT_PATH}/bin/gitlab-shell #{@key_id}\",no-port-forwarding,no-X11-forwarding,no-agent-forwarding,no-pty #{@key}"
     cmd = "echo \'#{cmd}\' >> #{auth_file}"
     system(cmd)
   end
 
   def rm_key
+    $logger.info "Removing key #{@key_id}"
     cmd = "sed -i '/shell #{@key_id}\"/d' #{auth_file}"
     system(cmd)
   end

lib/gitlab_logger.rb

+require 'logger'
+
+require_relative 'gitlab_config'
+
+def convert_log_level log_level
+  Logger.const_get(log_level.upcase)
+rescue NameError
+  $stderr.puts "WARNING: Unrecognized log level #{log_level.inspect}."
+  $stderr.puts "WARNING: Falling back to INFO."
+  Logger::INFO
+end
+
+config = GitlabConfig.new
+
+$logger = Logger.new(config.log_file)
+$logger.level = convert_log_level(config.log_level)

lib/gitlab_net.rb

@@ -3,6 +3,7 @@ require 'openssl'
 require 'json'
 
 require_relative 'gitlab_config'
+require_relative 'gitlab_logger'
 
 class GitlabNet
   def allowed?(cmd, repo, key, ref)
@@ -13,7 +14,6 @@ class GitlabNet
     key_id = key.gsub("key-", "")
 
     url = "#{host}/allowed?key_id=#{key_id}&action=#{cmd}&ref=#{ref}&project=#{project_name}"
-
     resp = get(url)
 
     !!(resp.code == '200' && resp.body == 'true')
@@ -40,6 +40,8 @@ class GitlabNet
   end
 
   def get(url)
+    $logger.debug "Performing GET #{url}"
+
     url = URI.parse(url)
     http = Net::HTTP.new(url.host, url.port)
 
@@ -57,7 +59,13 @@ class GitlabNet
       request.basic_auth config.http_settings['user'], config.http_settings['password']
     end
 
-    http.start {|http| http.request(request) }
+    http.start {|http| http.request(request) }.tap do |resp|
+      if resp.code == "200"
+        $logger.debug { "Received response #{resp.code} => <#{resp.body}>." }
+      else
+        $logger.error { "API call <GET #{url}> failed: #{resp.code} => <#{resp.body}>." }
+      end
+    end
   end
 
   def cert_store

lib/gitlab_projects.rb

@@ -2,6 +2,7 @@ require 'open3'
 require 'fileutils'
 
 require_relative 'gitlab_config'
+require_relative 'gitlab_logger'
 
 class GitlabProjects
   # Project name is a directory name for repository with .git at the end
@@ -31,6 +32,7 @@ class GitlabProjects
     when 'import-project'; import_project
     when 'fork-project'; fork_project
     else
+      $logger.warn "Attempt to execute invalid gitlab-projects command #{@command.inspect}."
       puts 'not allowed'
       false
     end
@@ -39,6 +41,7 @@ class GitlabProjects
   protected
 
   def add_project
+    $logger.info "Adding project #{@project_name} at <#{full_path}>."
     FileUtils.mkdir_p(full_path, mode: 0770)
     cmd = "cd #{full_path} && git init --bare && #{create_hooks_cmd}"
     system(cmd)
@@ -49,6 +52,7 @@ class GitlabProjects
   end
 
   def rm_project
+    $logger.info "Removing project #{@project_name} from <#{full_path}>."
     FileUtils.rm_rf(full_path)
   end
 
@@ -56,6 +60,7 @@ class GitlabProjects
   # URL must be publicly clonable
   def import_project
     @source = ARGV.shift
+    $logger.info "Importing project #{@project_name} from <#{@source}> to <#{full_path}>."
     cmd = "cd #{repos_path} && git clone --bare #{@source} #{project_name} && #{create_hooks_cmd}"
     system(cmd)
   end
@@ -71,15 +76,26 @@ class GitlabProjects
   def mv_project
     new_path = ARGV.shift
 
-    return false unless new_path
+    unless new_path
+      $logger.error "mv-project failed: no destination path provided."
+      return false
+    end
 
     new_full_path = File.join(repos_path, new_path)
 
-    # check if source repo exists
-    # and target repo does not exist
-    return false unless File.exists?(full_path)
-    return false if File.exists?(new_full_path)
+    # verify that the source repo exists
+    unless File.exists?(full_path)
+      $logger.error "mv-project failed: source path <#{full_path}> does not exist."
+      return false
+    end
+
+    # ...and that the target repo does not exist
+    if File.exists?(new_full_path)
+      $logger.error "mv-project failed: destination path <#{new_full_path}> already exists."
+      return false
+    end
 
+    $logger.info "Moving project #{@project_name} from <#{full_path}> to <#{new_full_path}>."
     FileUtils.mv(full_path, new_full_path)
   end
 
@@ -87,16 +103,26 @@ class GitlabProjects
     new_namespace = ARGV.shift
 
     # destination namespace must be provided
-    return false unless new_namespace
+    unless new_namespace
+      $logger.error "fork-project failed: no destination namespace provided."
+      return false
+    end
 
-    #destination namespace must exist
+    # destination namespace must exist
     namespaced_path = File.join(repos_path, new_namespace)
-    return false unless File.exists?(namespaced_path)
+    unless File.exists?(namespaced_path)
+      $logger.error "fork-project failed: destination namespace <#{namespaced_path}> does not exist."
+      return false
+    end
 
-    #a project of the same name cannot already be within the destination namespace
+    # a project of the same name cannot already be within the destination namespace
     full_destination_path = File.join(namespaced_path, project_name.split('/')[-1])
-    return false if File.exists?(full_destination_path)
+    if File.exists?(full_destination_path)
+      $logger.error "fork-project failed: destination repository <#{full_destination_path}> already exists."
+      return false
+    end
 
+    $logger.info "Forking project from <#{full_path}> to <#{full_destination_path}>."
     cmd = "cd #{namespaced_path} && git clone --bare #{full_path} && #{create_hooks_to(full_destination_path)}"
     system(cmd)
   end
@@ -108,7 +134,6 @@ class GitlabProjects
     up_hook_path = File.join(ROOT_PATH, 'hooks', 'update')
 
     "ln -s #{pr_hook_path} #{dest_path}/hooks/post-receive && ln -s #{up_hook_path} #{dest_path}/hooks/update"
-
   end
 
 end

lib/gitlab_shell.rb

@@ -8,7 +8,9 @@ class GitlabShell
   def initialize
     @key_id = /key-[0-9]+/.match(ARGV.join).to_s
     @origin_cmd = ENV['SSH_ORIGINAL_COMMAND']
-    @repos_path = GitlabConfig.new.repos_path
+    @config = GitlabConfig.new
+    @repos_path = @config.repos_path
+    @user_tried = false
   end
 
   def exec
@@ -20,13 +22,18 @@ class GitlabShell
 
         if validate_access
           process_cmd
+        else
+          message = "gitlab-shell: Access denied for git command <#{@origin_cmd}> by #{log_username}."
+          $logger.warn message
+          $stderr.puts "Access denied."
         end
       else
+        message = "gitlab-shell: Attempt to execute disallowed command <#{@origin_cmd}> by #{log_username}."
+        $logger.warn message
         puts 'Not allowed command'
       end
     else
-      user = api.discover(@key_id)
-      puts "Welcome to GitLab, #{user && user['name'] || 'Anonymous'}!"
+      puts "Welcome to GitLab, #{username}!"
     end
   end
 
@@ -44,7 +51,9 @@ class GitlabShell
 
   def process_cmd
     repo_full_path = File.join(repos_path, repo_name)
-    exec_cmd "#{@git_cmd} #{repo_full_path}"
+    cmd = "#{@git_cmd} #{repo_full_path}"
+    $logger.info "gitlab-shell: executing git command <#{cmd}> for #{log_username}."
+    exec_cmd(cmd)
   end
 
   def validate_access
@@ -58,4 +67,23 @@ class GitlabShell
   def api
     GitlabNet.new
   end
+
+  def user
+    # Can't use "@user ||=" because that will keep hitting the API when @user is really nil!
+    if @user_tried
+      @user
+    else
+      @user_tried = true
+      @user = api.discover(@key_id)
+    end
+  end
+
+  def username
+    user && user['name'] || 'Anonymous'
+  end
+
+  # User identifier to be used in log messages.
+  def log_username
+    @config.audit_usernames ? username : "user with key #{@key_id}"
+  end
 end

spec/gitlab_keys_spec.rb

@@ -2,6 +2,10 @@ require_relative 'spec_helper'
 require_relative '../lib/gitlab_keys'
 
 describe GitlabKeys do
+  before do
+    $logger = double('logger').as_null_object
+  end
+
   describe :initialize do
     let(:gitlab_keys) { build_gitlab_keys('add-key', 'key-741', 'ssh-rsa AAAAB3NzaDAxx2E') }
 
@@ -18,6 +22,11 @@ describe GitlabKeys do
       gitlab_keys.should_receive(:system).with(valid_cmd)
       gitlab_keys.send :add_key
     end
+
+    it "should log an add-key event" do
+      $logger.should_receive(:info).with('Adding key key-741 => "ssh-rsa AAAAB3NzaDAxx2E"')
+      gitlab_keys.send :add_key
+    end
   end
 
   describe :rm_key do
@@ -28,6 +37,11 @@ describe GitlabKeys do
       gitlab_keys.should_receive(:system).with(valid_cmd)
       gitlab_keys.send :rm_key
     end
+
+    it "should log an rm-key event" do
+      $logger.should_receive(:info).with('Removing key key-741')
+      gitlab_keys.send :rm_key
+    end
   end
 
   describe :exec do
@@ -48,6 +62,13 @@ describe GitlabKeys do
       gitlab_keys.should_receive(:puts).with('not allowed')
       gitlab_keys.exec
     end
+
+    it 'should log a warning on unknown commands' do
+      gitlab_keys = build_gitlab_keys('nooope')
+      gitlab_keys.stub(puts: nil)
+      $logger.should_receive(:warn).with('Attempt to execute invalid gitlab-keys command "nooope".')
+      gitlab_keys.exec
+    end
   end
 
   def build_gitlab_keys(*args)

spec/gitlab_projects_spec.rb

@@ -4,6 +4,7 @@ require_relative '../lib/gitlab_projects'
 describe GitlabProjects do
   before do
     FileUtils.mkdir_p(tmp_repos_path)
+    $logger = double('logger').as_null_object
   end
 
   after do
@@ -37,10 +38,16 @@ describe GitlabProjects do
       gl_projects.should_receive(:system).with(valid_cmd)
       gl_projects.exec
     end
+
+    it "should log an add-project event" do
+      $logger.should_receive(:info).with("Adding project #{repo_name} at <#{tmp_repo_path}>.")
+      gl_projects.exec
+    end
   end
 
   describe :mv_project do
     let(:gl_projects) { build_gitlab_projects('mv-project', repo_name, 'repo.git') }
+    let(:new_repo_path) { File.join(tmp_repos_path, 'repo.git') }
 
     before do
       FileUtils.mkdir_p(tmp_repo_path)
@@ -50,7 +57,33 @@ describe GitlabProjects do
       File.exists?(tmp_repo_path).should be_true
       gl_projects.exec
       File.exists?(tmp_repo_path).should be_false
-      File.exists?(File.join(tmp_repos_path, 'repo.git')).should be_true
+      File.exists?(new_repo_path).should be_true
+    end
+
+    it "should fail if no destination path is provided" do
+      incomplete = build_gitlab_projects('mv-project', repo_name)
+      $logger.should_receive(:error).with("mv-project failed: no destination path provided.")
+      incomplete.exec.should be_false
+    end
+
+    it "should fail if the source path doesn't exist" do
+      bad_source = build_gitlab_projects('mv-project', 'bad-src.git', 'dest.git')
+      $logger.should_receive(:error).with("mv-project failed: source path <#{tmp_repos_path}/bad-src.git> does not exist.")
+      bad_source.exec.should be_false
+    end
+
+    it "should fail if the destination path already exists" do
+      FileUtils.mkdir_p(File.join(tmp_repos_path, 'already-exists.git'))
+      bad_dest = build_gitlab_projects('mv-project', repo_name, 'already-exists.git')
+      message = "mv-project failed: destination path <#{tmp_repos_path}/already-exists.git> already exists."
+      $logger.should_receive(:error).with(message)
+      bad_dest.exec.should be_false
+    end
+
+    it "should log an mv-project event" do
+      message = "Moving project #{repo_name} from <#{tmp_repo_path}> to <#{new_repo_path}>."
+      $logger.should_receive(:info).with(message)
+      gl_projects.exec
     end
   end
 
@@ -66,6 +99,11 @@ describe GitlabProjects do
       gl_projects.exec
       File.exists?(tmp_repo_path).should be_false
     end
+
+    it "should log an rm-project event" do
+      $logger.should_receive(:info).with("Removing project #{repo_name} from <#{tmp_repo_path}>.")
+      gl_projects.exec
+    end
   end
 
   describe :import_project do
@@ -75,6 +113,12 @@ describe GitlabProjects do
       gl_projects.exec
       File.exists?(File.join(tmp_repo_path, 'HEAD')).should be_true
     end
+
+    it "should log an import-project event" do
+      message = "Importing project #{repo_name} from <https://github.com/randx/six.git> to <#{tmp_repo_path}>."
+      $logger.should_receive(:info).with(message)
+      gl_projects.exec
+    end
   end
 
   describe :fork_project do
@@ -87,7 +131,15 @@ describe GitlabProjects do
       gl_projects_import.exec
     end
 
+    it "should not fork without a destination namespace" do
+      missing_arg = build_gitlab_projects('fork-project', source_repo_name)
+      $logger.should_receive(:error).with("fork-project failed: no destination namespace provided.")
+      missing_arg.exec.should be_false
+    end
+
     it "should not fork into a namespace that doesn't exist" do
+      message = "fork-project failed: destination namespace <#{tmp_repos_path}/forked-to-namespace> does not exist."
+      $logger.should_receive(:error).with(message)
       gl_projects_fork.exec.should be_false
     end
 
@@ -101,9 +153,24 @@ describe GitlabProjects do
     end
 
     it "should not fork if a project of the same name already exists" do
-      #trying to fork again should fail as the repo already exists
+      # create a fake project at the intended destination
+      FileUtils.mkdir_p(File.join(tmp_repos_path, 'forked-to-namespace', repo_name))
+
+      # trying to fork again should fail as the repo already exists
+      message = "fork-project failed: destination repository <#{tmp_repos_path}/forked-to-namespace/#{repo_name}> "
+      message << "already exists."
+      $logger.should_receive(:error).with(message)
       gl_projects_fork.exec.should be_false
     end
+
+    it "should log a fork-project event" do
+      message = "Forking project from <#{File.join(tmp_repos_path, source_repo_name)}> to <#{dest_repo}>."
+      $logger.should_receive(:info).with(message)
+
+      # create destination namespace
+      FileUtils.mkdir_p(File.join(tmp_repos_path, 'forked-to-namespace'))
+      gl_projects_fork.exec.should be_true
+    end
   end
 
   describe :exec do
@@ -112,6 +179,12 @@ describe GitlabProjects do
       gitlab_projects.should_receive(:puts).with('not allowed')
       gitlab_projects.exec
     end
+
+    it 'should log a warning for unknown commands' do
+      gitlab_projects = build_gitlab_projects('hurf-durf', repo_name)
+      $logger.should_receive(:warn).with('Attempt to execute invalid gitlab-projects command "hurf-durf".')
+      gitlab_projects.exec
+    end
   end
 
   def build_gitlab_projects(*args)

spec/gitlab_shell_spec.rb

@@ -11,13 +11,15 @@ describe GitlabShell do
   end
   let(:api) do
     double(GitlabNet).tap do |api|
-      api.stub(discover: 'John Doe')
+      api.stub(discover: { 'name' => 'John Doe' })
       api.stub(allowed?: true)
     end
   end
   let(:key_id) { "key-#{rand(100) + 100}" }
   let(:repository_path) { "/home/git#{rand(100)}/repos" }
-  before { GitlabConfig.any_instance.stub(:repos_path).and_return(repository_path) }
+  before do
+    GitlabConfig.any_instance.stub(repos_path: repository_path, audit_usernames: false)
+  end
 
   describe :initialize do
     before { ssh_cmd 'git-receive-pack' }
@@ -64,6 +66,18 @@ describe GitlabShell do
       it "should set the GL_ID environment variable" do
         ENV.should_receive("[]=").with("GL_ID", key_id)
       end
+
+      it "should log the command execution" do
+        message = "gitlab-shell: executing git command "
+        message << "<git-upload-pack #{File.join(repository_path, 'gitlab-ci.git')}> "
+        message << "for user with key #{key_id}."
+        $logger.should_receive(:info).with(message)
+      end
+
+      it "should use usernames if configured to do so" do
+        GitlabConfig.any_instance.stub(audit_usernames: true)
+        $logger.should_receive(:info) { |msg| msg.should =~ /for John Doe/ }
+      end
     end
 
     context 'git-receive-pack' do
@@ -77,6 +91,13 @@ describe GitlabShell do
       it "should execute the command" do
         subject.should_receive(:exec_cmd).with("git-receive-pack #{File.join(repository_path, 'gitlab-ci.git')}")
       end
+
+      it "should log the command execution" do
+        message = "gitlab-shell: executing git command "
+        message << "<git-receive-pack #{File.join(repository_path, 'gitlab-ci.git')}> "
+        message << "for user with key #{key_id}."
+        $logger.should_receive(:info).with(message)
+      end
     end
 
     context 'arbitrary command' do
@@ -90,6 +111,11 @@ describe GitlabShell do
       it "should not execute the command" do
         subject.should_not_receive(:exec_cmd)
       end
+
+      it "should log the attempt" do
+        message = "gitlab-shell: Attempt to execute disallowed command <arbitrary command> by user with key #{key_id}."
+        $logger.should_receive(:warn).with(message)
+      end
     end
 
     context 'no command' do
@@ -110,6 +136,13 @@ describe GitlabShell do
       api.should_receive(:allowed?).
         with('git-upload-pack', 'gitlab-ci.git', key_id, '_any')
     end
+
+    it "should disallow access and log the attempt if allowed? returns false" do
+      api.stub(allowed?: false)
+      message = "gitlab-shell: Access denied for git command <git-upload-pack gitlab-ci.git> "
+      message << "by user with key #{key_id}."
+      $logger.should_receive(:warn).with(message)
+    end
   end
 
   def ssh_cmd(cmd)