Adding more descriptive logging (#87)

DARPA-ASKEM · Jul 17, 2023 · 78fb0ad · 78fb0ad
1 parent e37b8b5
commit 78fb0ad
Show file tree

Hide file tree

Showing 2 changed files with 19 additions and 9 deletions.
diff --git a/Project.toml b/Project.toml
@@ -1,7 +1,7 @@
 name = "SimulationService"
 uuid = "e66378d9-a322-4933-8764-0ce0bcab4993"
 authors = ["Five Grant <[email protected]>"]
-version = "0.11.0"
+version = "0.12.0"
 
 [deps]
 AMQPClient = "79c8b4cd-a41a-55fa-907c-fab5288e1383"

diff --git a/src/SimulationService.jl b/src/SimulationService.jl
@@ -183,6 +183,13 @@ Base.@kwdef mutable struct OperationRequest
     result::Any = nothing                               # store result of job
 end
 
+function Base.show(io::IO, o::OperationRequest)
+    println(io, "OperationRequest")
+    println(io, "  obj with keys: $(keys(o.obj))")
+    println(io, "             id: $(o.id)")
+    println(io, "      operation: $(o.operation)")
+end
+
 function OperationRequest(req::HTTP.Request, operation_name::String)
     o = OperationRequest()
     o.obj = JSON3.read(req.body)
@@ -196,14 +203,15 @@ function OperationRequest(req::HTTP.Request, operation_name::String)
         k == :model ? (o.model = v) :
         k == :local_model_file ? (o.model = JSON3.read(v, Config)) :  # For testing only
         k == :local_csv_file ? (o.df = CSV.read(v, DataFrame)) :      # For testing only
-        @info "Unprocessed key: $k"
+        nothing
     end
     return o
 end
 
 Config(o::OperationRequest) = Config(k => getfield(o,k) for k in fieldnames(OperationRequest))
 
 function solve(o::OperationRequest)
+    @info "solve: $o"
     callback = get_callback(o)
     T = operations2type[o.operation]
     op = T(o)
@@ -256,6 +264,7 @@ end
 # Each function in this section needs to handle both cases: ENABLE_TDS=true and ENABLE_TDS=false
 
 function DataServiceModel(id::String)
+    @info "DataServiceModel($(repr(id)))"
     if !ENABLE_TDS[]
         @warn "TDS disabled - `DataServiceModel` with argument $id"
         return DataServiceModel()  # TODO: mock TDS
@@ -272,6 +281,7 @@ function DataServiceModel(id::String)
 end
 
 function get_model(id::String)
+    @info "get_model($(repr(id)))"
     if !ENABLE_TDS[]
         @warn "TDS disabled - `get_model` with argument $id"
         return Config()  # TODO: mock TDS
@@ -280,20 +290,21 @@ function get_model(id::String)
 end
 
 function get_dataset(obj::Config)
+    @info "get_dataset with obj = $(JSON3.write(obj))"
     if !ENABLE_TDS[]
         @warn "TDS disabled - `get_dataset` with argument $obj"
         return DataFrame()  # TODO: mock tds
     end
     tds_url = "$(TDS_URL[])/datasets/$(obj.id)/download-url?filename=$(obj.filename)"
     s3_url = get_json(tds_url).url
-    df = CSV.read(download(s3_url), DataFrame)  # !!! <-- ONLY FAILURE ON OUR TEST INSTANCE OF TDS !!!
+    df = CSV.read(download(s3_url), DataFrame)
     return rename!(df, Dict{String,String}(string(k) => string(v) for (k,v) in obj.mappings))
 end
 
 # published as JSON3.write(content)
 function publish_to_rabbitmq(content)
     if !RABBITMQ_ENABLED[]
-        @warn "RabbitMQ disabled - `publish_to_rabbitmq` with argument $content"
+        @warn "RabbitMQ disabled - `publish_to_rabbitmq` with content $(JSON3.write(content))"
         return content
     end
     json = Vector{UInt8}(codeunits(JSON3.write(content)))
@@ -305,6 +316,7 @@ publish_to_rabbitmq(; kw...) = publish_to_rabbitmq(Dict(kw...))
 
 # initialize the DataServiceModel in TDS: POST /simulations/{id}
 function create(o::OperationRequest)
+    @info "creating model in TDS from: $o"
     m = DataServiceModel(o)
     body = JSON3.write(m)
     if !ENABLE_TDS[]
@@ -317,6 +329,7 @@ end
 # update the DataServiceModel in TDS: PUT /simulations/{id}
 # kw args and their types much match field::fieldtype in DataServiceModel
 function update(o::OperationRequest; kw...)
+    @info "updating model $(o.id) in TDS: $(NamedTuple(kw))"
     if !ENABLE_TDS[]
         @warn "TDS disabled - `update` OperationRequest with id=$(o.id), $kw"
         return kw
@@ -332,6 +345,7 @@ end
 
 function complete(o::OperationRequest)
     isnothing(o.result) && error("No result.  Run `solve(o::OperationRequest)` first.")
+    @info "completing model $(o.id) in TDS: summary(result) = $(summary(o.result))"
 
     if o.result isa DataFrame
         # DataFrame uploaded as CSV file
@@ -374,18 +388,14 @@ last_job = Ref{JobSchedulers.Job}()
 # 6) We upload results to S3: PUT $url
 # 7) We update simulation in TDS(status="complete", complete_time=<datetime>): PUT /simulations/$id
 function operation(request::HTTP.Request, operation_name::String)
-    @info "operation requested: $operation_name"
+    @info "Creating OperationRequest from POST to route $operation_name"
     o = OperationRequest(request, operation_name)  # 1, 3
-    @info "Creating in TDS (id=$(o.id)))..."
     create(o)  # 2
     job = JobSchedulers.Job(
         @task begin
             try
-                @info "Updating job $(o.id)"
                 update(o; status = "running", start_time = timestamp()) # 4
-                @info "Solving job $(o.id)"
                 solve(o) # 5
-                @info "Completing job $(o.id)"
                 complete(o)  # 6, 7
             catch ex
                 update(o; status = "error", reason = string(ex))