[PATCH compass-ci] fix: scheduler: cut down log - Compass-ci

21 Oct 2020

[why]
when consume with "No job now", scheduler output 14 lines log.
when submit 1 job and consume it, scheduler output 78 lines log.
it is a bit of heavy for log collect and some logs are redundancy.
[how]
1.merge 4 lines to 1 line (form to json) for debug_message.
2.remove output "Done", it's same with kemal-frame meesage "200 GET/PUT..."
3.only 0 | 1 extra message for 1 API: if there has an active message, do
  not call debug_message
as default, there has 1 kemal-frame message for each API
  2020-10-20 09:40:28 UTC 200 GET /boot.ipxe/mac/0a-4c-34-18-0a-17 7.18ms
  <time in> <response status> <----request API---->  <response time span>
[now]
this patch cut 92 lines log to 26 line, interactive with 15 API.
examples:
--- <4 to 1> and <remove single "Done">
...
...
172.168.131.113:29720
<< Done
 2020-10... 200 PUT /set_host_mac?hostname=vm... 289.2µs
-->
 2020-10... 200 PUT /set_host_mac?hostname=vm... 977.56µs
--- <0 | 1 extra message>
...
...
172.18.222.81:44210
<< Done
 {"job_state":"running","job_id":"crystal.105070"}
 2020-10... 200 GET /~lkp/cgi-bin/lkp-jobfile-append-var?... 2.36ms
-->
 {"job_state":"running","job_id":"crystal.105071"}
 2020-10... UTC 200 GET /~lkp/cgi-bin/lkp-jobfile-append-var?... 2.8ms
Signed-off-by: Tong Qunfeng taxcom@tom.com
---
 src/lib/sched.cr           |  9 +++------
 src/scheduler/scheduler.cr | 30 ++++++++++--------------------
 2 files changed, 13 insertions(+), 26 deletions(-)

diff --git a/src/lib/sched.cr b/src/lib/sched.cr
index e6f353a..7215df5 100644
--- a/src/lib/sched.cr
+++ b/src/lib/sched.cr
@@ -317,7 +317,6 @@ class Sched
                       JobHelper.service_path("#{SRV_INITRD}/lkp/#{job.lkp_initrd_user}/lkp-#{job.arch}.cgz")
     response["job"] = "http://#%7BSCHED_HOST%7D:#%7BSCHED_PORT%7D/job_initrd_tmpfs/#%7Bjob.id%7D/jo..."
-    puts %({"job_id": "#{job.id}", "job_state": "boot"})
     return response.to_json
   end
@@ -339,7 +338,6 @@ class Sched
response += "boot\n"
-    puts %({"job_id": "#{job.id}", "job_state": "boot"})
     return response
   end
@@ -481,7 +479,6 @@ class Sched
     response += job.kernel_params
     response += "\nboot\n"
-    puts %({"job_id": "#{job.id}", "job_state": "boot"})
     return response
   end
@@ -512,7 +509,7 @@ class Sched
     # json log
     log = job_content.dup
     log["job_id"] = log.delete("id").not_nil!
-    puts log.to_json
+    return log.to_json
   end
def update_tbox_wtmp(env : HTTP::Server::Context)
@@ -541,7 +538,7 @@ class Sched
# json log
     hash["testbox"] = testbox
-    puts hash.to_json
+    return hash.to_json
   end
def report_ssh_port(testbox : String, ssh_port : String)
@@ -572,6 +569,6 @@ class Sched
@redis.remove_finished_job(job_id)
-    puts %({"job_id": "#{job_id}", "job_state": "complete"})
+    return %({"job_id": "#{job_id}", "job_state": "complete"})
   end
 end
diff --git a/src/scheduler/scheduler.cr b/src/scheduler/scheduler.cr
index e38d15c..5befcf9 100644
--- a/src/scheduler/scheduler.cr
+++ b/src/scheduler/scheduler.cr
@@ -34,9 +34,7 @@ module Scheduler
# for debug (maybe kemal debug|logger does better)
   def self.debug_message(env, response)
-    puts "\n\n"
-    puts ">> #{env.request.remote_address}"
-    puts "<< #{response}"
+    puts %({"from": "#{env.request.remote_address}", "response": #{response.to_json}})
   end
# echo alive
@@ -53,7 +51,8 @@ module Scheduler
   get "/boot.:boot_type/:parameter/:value" do |env|
     response = sched.find_job_boot(env)
-    debug_message(env, response)
+    job_id = response[/tmpfs/(.*)/job.cgz/, 1]?
+    puts %({"job_id": "#{job_id}", "job_state": "boot"}) if job_id
response
   end
@@ -62,7 +61,8 @@ module Scheduler
   get "/~lkp/cgi-bin/gpxelinux.cgi" do |env|
     response = sched.find_next_job_boot(env)
-    debug_message(env, response)
+    job_id = response[/tmpfs/(.*)/job.cgz/, 1]?
+    puts %({"job_id": "#{job_id}", "job_state": "boot"}) if job_id
response
   end
@@ -87,7 +87,6 @@ module Scheduler
     file_path = ::File.join [Kemal.config.public_folder, job_id, job_package]
puts %({"job_id": "#{job_id}", "job_state": "download"})
-    debug_message(env, file_path)
send_file env, file_path
   end
@@ -102,8 +101,6 @@ module Scheduler
     if (client_hostname = env.params.query["hostname"]?) && (client_mac = env.params.query["mac"]?)
       sched.set_host_mac(client_mac, client_hostname)
-      debug_message(env, "Done")
-
       "Done"
     else
       "No yet!"
@@ -115,8 +112,6 @@ module Scheduler
     if client_mac = env.params.query["mac"]?
       sched.del_host_mac(client_mac)
-      debug_message(env, "Done")
-
       "Done"
     else
       "No yet!"
@@ -129,10 +124,8 @@ module Scheduler
   #  ?job_file=/lkp/scheduled/job.yaml&job_state=post_run&job_id=10
   #  ?job_file=/lkp/scheduled/job.yaml&loadavg=0.28 0.82 0.49 1/105 3389&start_time=1587725398&end_time=1587725698&job_id=10
   get "/~lkp/cgi-bin/lkp-jobfile-append-var" do |env|
-    # get job_id from request
-    debug_message(env, "Done")
+    puts sched.update_job_parameter(env)
-    sched.update_job_parameter(env)
     "Done"
   end
@@ -168,17 +161,15 @@ module Scheduler
     # get job_id from request
     job_id = env.params.query["job_id"]?
     if job_id
-      debug_message(env, "Done")
-
-      sched.close_job(job_id)
+      puts sched.close_job(job_id)
     end
+
     "Done"
   end
get "/~lkp/cgi-bin/lkp-wtmp" do |env|
-    debug_message(env, "Done")
+    puts sched.update_tbox_wtmp(env)
-    sched.update_tbox_wtmp(env)
     "Done"
   end
@@ -188,12 +179,11 @@ module Scheduler
     job_id = env.params.query["job_id"].to_s
if testbox && ssh_port
-      debug_message(env, "Done")
-
       sched.report_ssh_port(testbox, ssh_port)
     end
puts %({"job_id": "#{job_id}", "state": "set ssh port", "ssh_port": "#{ssh_port}", "tbox_name": "#{testbox}"})
+
     "Done"
   end
 end
-- 
2.23.0

    