[clang] improve debug logs

Summary:
- log trans_state for each instruction
- create boxes to indent logs
- hunt down "@." that would prematurely close the boxes
- improve messages

Reviewed By: ngorogiannis

Differential Revision: D24794798

fbshipit-source-id: 80d51a8c5

infer/src/clang/cScope.ml

@@ -210,7 +210,9 @@ module Variables = struct
   let empty_scope = {current= []; current_kind= InitialScope; outers= []}
 
   let compute_vars_to_destroy_map body =
-    visit_stmt body (empty_scope, ClangPointers.Map.empty) |> snd
+    let scope_map = visit_stmt body (empty_scope, ClangPointers.Map.empty) |> snd in
+    L.debug Capture Verbose "@\n" ;
+    scope_map
 end
 
 module CXXTemporaries = struct
@@ -266,5 +268,8 @@ module CXXTemporaries = struct
         visit_stmt context stmt temporaries )
 
 
-  let get_destroyable_temporaries context stmt_list = visit_stmt_list context stmt_list []
+  let get_destroyable_temporaries context stmt_list =
+    let temporaries = visit_stmt_list context stmt_list [] in
+    L.debug Capture Verbose "@\n" ;
+    temporaries
 end

infer/src/clang/cTrans.ml

@@ -475,12 +475,12 @@ module CTrans_funct (F : CModule_type.CFrontend) : CModule_type.CTranslation = s
     in
     let name_info, decl_ptr, qual_type = CAst_utils.get_info_from_decl_ref decl_ref in
     let field_string = name_info.Clang_ast_t.ni_name in
-    L.(debug Capture Verbose) "Translating field '%s'@\n" field_string ;
+    L.debug Capture Verbose "Translating field '%s'@\n" field_string ;
     let field_typ = CType_decl.qual_type_to_sil_type context.tenv qual_type in
     let obj_sil, class_typ = pre_trans_result.return in
     let is_pointer_typ = Typ.is_pointer class_typ in
     let class_typ = match class_typ.Typ.desc with Typ.Tptr (t, _) -> t | _ -> class_typ in
-    L.(debug Capture Verbose) "Type is  '%s' @." (Typ.to_string class_typ) ;
+    L.debug Capture Verbose "Type is  '%s' @\n" (Typ.to_string class_typ) ;
     let class_tname =
       match CAst_utils.get_decl decl_ptr with
       | Some (FieldDecl ({di_parent_pointer}, _, _, _))
@@ -535,7 +535,7 @@ module CTrans_funct (F : CModule_type.CFrontend) : CModule_type.CTranslation = s
     let decl_opt = CAst_utils.get_function_decl_with_body decl_ptr in
     Option.iter ~f:(call_translation context) decl_opt ;
     let method_name = CAst_utils.get_unqualified_name name_info in
-    L.(debug Capture Verbose) "!!!!! Dealing with method '%s' @." method_name ;
+    L.debug Capture Verbose "!!!!! Dealing with method '%s'@\n" method_name ;
     let ms_opt = CMethod_trans.method_signature_of_pointer context.tenv decl_ptr in
     let is_instance_method =
       match ms_opt with
@@ -841,7 +841,8 @@ module CTrans_funct (F : CModule_type.CFrontend) : CModule_type.CTranslation = s
         sizeof_expr_class (CContext.get_curr_class_typename stmt_info context)
       else (var_exp, typ)
     in
-    L.(debug Capture Verbose) "@\n@\n PVAR ='%s'@\n@\n" (Pvar.to_string pvar) ;
+    L.debug Capture Verbose "var_deref_trans for %a:%a@\n@\n" (Pvar.pp Pp.text) pvar
+      (Typ.pp Pp.text) typ ;
     let res_trans = mk_trans_result return empty_control in
     let res_trans =
       match typ.desc with
@@ -866,9 +867,6 @@ module CTrans_funct (F : CModule_type.CFrontend) : CModule_type.CTranslation = s
 
 
   and decl_ref_trans ?(is_constructor_init = false) ~context trans_state stmt_info decl_ref =
-    L.(debug Capture Verbose)
-      "  priority node free = '%s'@\n@."
-      (string_of_bool (PriorityNode.is_priority_free trans_state)) ;
     let decl_kind = decl_ref.Clang_ast_t.dr_kind in
     match (decl_kind, context) with
     | `EnumConstant, _ ->
@@ -891,9 +889,6 @@ module CTrans_funct (F : CModule_type.CFrontend) : CModule_type.CTranslation = s
 
 
   and declRefExpr_trans trans_state stmt_info decl_ref_expr_info =
-    L.(debug Capture Verbose)
-      "  priority node free = '%b'@\n@."
-      (PriorityNode.is_priority_free trans_state) ;
     let decl_ref = Option.value_exn decl_ref_expr_info.Clang_ast_t.drti_decl_ref in
     decl_ref_trans ~context:DeclRefExpr trans_state stmt_info decl_ref
 
@@ -985,13 +980,9 @@ module CTrans_funct (F : CModule_type.CFrontend) : CModule_type.CTranslation = s
 
 
   and binaryOperator_trans trans_state binary_operator_info stmt_info expr_info stmt_list =
-    L.(debug Capture Verbose)
+    L.debug Capture Verbose "  BinaryOperator '%a' "
-      "  BinaryOperator '%a' "
       (Pp.of_string ~f:Clang_ast_j.string_of_binary_operator_kind)
       binary_operator_info.Clang_ast_t.boi_kind ;
-    L.(debug Capture Verbose)
-      "  priority node free = '%s'@\n@."
-      (string_of_bool (PriorityNode.is_priority_free trans_state)) ;
     let context = trans_state.context in
     let trans_state_pri = PriorityNode.try_claim_priority_node trans_state stmt_info in
     let node_name =
@@ -1357,9 +1348,6 @@ module CTrans_funct (F : CModule_type.CFrontend) : CModule_type.CTranslation = s
 
 
   and objCMessageExpr_trans trans_state si obj_c_message_expr_info stmt_list expr_info =
-    L.(debug Capture Verbose)
-      "  priority node free = '%s'@\n@."
-      (string_of_bool (PriorityNode.is_priority_free trans_state)) ;
     let context = trans_state.context in
     let sil_loc = CLocation.location_of_stmt_info context.translation_unit_context.source_file si in
     let method_type_no_ref = CType_decl.get_type_from_expr_info expr_info context.CContext.tenv in
@@ -2466,6 +2454,12 @@ module CTrans_funct (F : CModule_type.CFrontend) : CModule_type.CTranslation = s
 
   and init_expr_trans ?(is_initListExpr_builtin = false) trans_state var_exp_typ ?qual_type
       var_stmt_info init_expr_opt =
+    L.debug Capture Verbose "init_expr_trans %b %a %a <?qual_type> <stmt_info> %a@\n"
+      is_initListExpr_builtin pp_trans_state trans_state
+      (Pp.pair ~fst:Exp.pp ~snd:(Typ.pp Pp.text_break))
+      var_exp_typ
+      (Pp.option (Pp.of_string ~f:Clang_ast_proj.get_stmt_kind_string))
+      init_expr_opt ;
     match init_expr_opt with
     | None -> (
       match Option.bind qual_type ~f:(fun qt -> CAst_utils.get_type qt.Clang_ast_t.qt_type_ptr) with
@@ -2495,9 +2489,13 @@ module CTrans_funct (F : CModule_type.CFrontend) : CModule_type.CTranslation = s
           if
             (* variable might be initialized already - do nothing in that case*)
             List.exists ~f:(Exp.equal var_exp) res_trans_ie.control.initd_exps
-          then None
+          then (
+            L.debug Capture Verbose "Sub-expr already initialized %a@\n" Exp.pp var_exp ;
+            None )
           else
             let sil_e1', ie_typ = res_trans_ie.return in
+            L.debug Capture Verbose "Sub-expr did not initialize %a, initializing with %a@\n" Exp.pp
+              var_exp Exp.pp sil_e1' ;
             Some
               { empty_control with
                 instrs=
@@ -2519,9 +2517,13 @@ module CTrans_funct (F : CModule_type.CFrontend) : CModule_type.CTranslation = s
           Option.to_list pre_init_opt
           @ (res_trans_ie.control :: Option.to_list assign_trans_control_opt)
         in
-        PriorityNode.compute_controls_to_parent trans_state_pri sil_loc ~node_name:DeclStmt
+        L.debug Capture Verbose "all_res_trans=%a@\n" (Pp.seq ~sep:";" pp_control) all_res_trans ;
-          var_stmt_info all_res_trans
+        let control =
-        |> mk_trans_result var_exp_typ
+          PriorityNode.compute_controls_to_parent trans_state_pri sil_loc ~node_name:DeclStmt
+            var_stmt_info all_res_trans
+        in
+        L.debug Capture Verbose "combined: %a@." pp_control control ;
+        mk_trans_result var_exp_typ control
 
 
   and collect_all_decl trans_state var_decls next_nodes stmt_info : trans_result =
@@ -2600,9 +2602,6 @@ module CTrans_funct (F : CModule_type.CFrontend) : CModule_type.CTranslation = s
 
   (** For OpaqueValueExpr we return the translation generated from its source expression*)
   and opaqueValueExpr_trans trans_state opaque_value_expr_info source_range =
-    L.(debug Capture Verbose)
-      "  priority node free = '%s'@\n@."
-      (string_of_bool (PriorityNode.is_priority_free trans_state)) ;
     match trans_state.opaque_exp with
     | Some exp ->
         mk_trans_result exp empty_control
@@ -2658,9 +2657,6 @@ module CTrans_funct (F : CModule_type.CFrontend) : CModule_type.CTranslation = s
   and cast_exprs_trans trans_state stmt_info stmt_list expr_info ?objc_bridge_cast_kind
       cast_expr_info =
     let context = trans_state.context in
-    L.(debug Capture Verbose)
-      "  priority node free = '%s'@\n@."
-      (string_of_bool (PriorityNode.is_priority_free trans_state)) ;
     let sil_loc =
       CLocation.location_of_stmt_info context.translation_unit_context.source_file stmt_info
     in
@@ -3758,10 +3754,10 @@ module CTrans_funct (F : CModule_type.CFrontend) : CModule_type.CTranslation = s
         let {Clang_ast_t.si_pointer}, _ = Clang_ast_proj.get_stmt_tuple instr in
         Format.pp_print_int f si_pointer
       in
-      L.(debug Capture Verbose)
+      L.debug Capture Verbose
-        "Translating statement '%a' (pointer= '%a')@\n@[<hv2>"
+        "Translating statement '%a' (pointer= '%a')@\n@[<hv2>  trans_state=%a@\n"
         (Pp.of_string ~f:Clang_ast_proj.get_stmt_kind_string)
-        instr pp_pointer instr ;
+        instr pp_pointer instr pp_trans_state trans_state ;
       let trans_result =
         try instruction_scope trans_state instr
         with e ->

infer/src/clang/cTrans_utils.ml

@@ -6,6 +6,7 @@
  *)
 
 open! IStd
+module F = Format
 module Hashtbl = Caml.Hashtbl
 
 (** Utility methods to support the translation of clang ast constructs into sil instructions. *)
@@ -103,6 +104,16 @@ type continuation =
   ; return_temp: bool
         (* true if temps should not be removed in the node but returned to ancestors *) }
 
+let pp_continuation fmt ({break; continue; return_temp}[@warning "+9"]) =
+  if List.is_empty break then F.pp_print_string fmt "empty"
+  else
+    F.fprintf fmt "@[{break=[%a];@;continue=[%a];@;return_temp=%b}@]"
+      (Pp.seq ~sep:";" Procdesc.Node.pp)
+      break
+      (Pp.seq ~sep:";" Procdesc.Node.pp)
+      continue return_temp
+
+
 let is_return_temp continuation =
   match continuation with Some cont -> cont.return_temp | _ -> false
 
@@ -117,6 +128,13 @@ let mk_cond_continuation cont =
 
 type priority_node = Free | Busy of Clang_ast_t.pointer
 
+let pp_priority_node fmt = function
+  | Free ->
+      F.pp_print_string fmt "Free"
+  | Busy pointer ->
+      F.fprintf fmt "Busy(%d)" pointer
+
+
 (** A translation state. It provides the translation function with the info it needs to carry on the
     translation. *)
 type trans_state =
@@ -131,6 +149,32 @@ type trans_state =
         (** Current to-be-translated instruction is being passed as argument to the given method in
             a position annotated with NS_NOESCAPE *) }
 
+let pp_trans_state fmt
+    ({ context= _
+     ; succ_nodes
+     ; continuation
+     ; priority
+     ; var_exp_typ
+     ; opaque_exp
+     ; is_fst_arg_objc_instance_method_call
+     ; passed_as_noescape_block_to }[@warning "+9"]) =
+  F.fprintf fmt
+    "@[{succ_nodes=[%a];@;\
+     continuation=%a@;\
+     priority=%a;@;\
+     var_exp_typ=%a;@;\
+     opaque_exp=%a;@;\
+     is_fst_arg_objc_instance_method_call=%b;@;\
+     passed_as_noescape_block_to=%a}@]"
+    (Pp.seq ~sep:";" Procdesc.Node.pp)
+    succ_nodes (Pp.option pp_continuation) continuation pp_priority_node priority
+    (Pp.option (Pp.pair ~fst:Exp.pp ~snd:(Typ.pp_full Pp.text_break)))
+    var_exp_typ
+    (Pp.option (Pp.pair ~fst:Exp.pp ~snd:(Typ.pp_full Pp.text_break)))
+    opaque_exp is_fst_arg_objc_instance_method_call (Pp.option Procname.pp)
+    passed_as_noescape_block_to
+
+
 let default_trans_state context =
   { context
   ; succ_nodes= []
@@ -148,6 +192,16 @@ type control =
   ; instrs: Sil.instr list
   ; initd_exps: Exp.t list }
 
+let pp_control fmt {root_nodes; leaf_nodes; instrs; initd_exps} =
+  F.fprintf fmt "@[{root_nodes=[%a];@;leaf_nodes=[%a];@;instrs=[%a];@;initd_exps=[%a]}@]"
+    (Pp.seq ~sep:";" Procdesc.Node.pp)
+    root_nodes
+    (Pp.seq ~sep:";" Procdesc.Node.pp)
+    leaf_nodes
+    (Pp.seq ~sep:";" (Sil.pp_instr ~print_types:false Pp.text_break))
+    instrs (Pp.seq ~sep:";" Exp.pp) initd_exps
+
+
 type trans_result =
   { control: control
   ; return: Exp.t * Typ.t
@@ -193,12 +247,12 @@ module PriorityNode = struct
   let try_claim_priority_node trans_state stmt_info =
     match trans_state.priority with
     | Free ->
-        L.(debug Capture Verbose)
+        L.debug Capture Verbose "Priority is free. Locking priority node in %d@\n"
-          "Priority is free. Locking priority node in %d@\n@." stmt_info.Clang_ast_t.si_pointer ;
+          stmt_info.Clang_ast_t.si_pointer ;
         {trans_state with priority= Busy stmt_info.Clang_ast_t.si_pointer}
-    | _ ->
+    | Busy _ ->
-        L.(debug Capture Verbose)
+        L.debug Capture Verbose "Priority is %a. No claim possible in %d@\n" pp_priority_node
-          "Priority busy in %d. No claim possible@\n@." stmt_info.Clang_ast_t.si_pointer ;
+          trans_state.priority stmt_info.Clang_ast_t.si_pointer ;
         trans_state
 
 
@@ -237,9 +291,15 @@ module PriorityNode = struct
       let root_nodes =
         if List.is_empty res_state.root_nodes then [node] else res_state.root_nodes
       in
-      {res_state with root_nodes; leaf_nodes= [node]; instrs= []} )
+      let res_state = {res_state with root_nodes; leaf_nodes= [node]; instrs= []} in
-    else (* The node is created by the parent. We just pass back nodes/leafs params *)
+      L.debug Capture Verbose "Created node %a, returning control %a@\n" Procdesc.Node.pp node
-      res_state
+        pp_control res_state ;
+      res_state )
+    else (
+      (* The node is created by the parent. We just pass back nodes/leafs params *)
+      L.debug Capture Verbose "Delegating node creation to parent with control %a@\n" pp_control
+        res_state ;
+      res_state )
 
 
   let compute_results_to_parent trans_state loc ~node_name stmt_info ~return trans_results =

infer/src/clang/cTrans_utils.mli

@@ -6,6 +6,7 @@
  *)
 
 open! IStd
+module F = Format
 
 (** Utility methods to support the translation of clang ast constructs into sil instructions. *)
 
@@ -29,6 +30,8 @@ type trans_state =
   ; is_fst_arg_objc_instance_method_call: bool
   ; passed_as_noescape_block_to: Procname.t option }
 
+val pp_trans_state : F.formatter -> trans_state -> unit
+
 val default_trans_state : CContext.t -> trans_state
 
 (** Part of the translation result that is (loosely) related to control flow graph construction.
@@ -43,6 +46,8 @@ type control =
         (** list of SIL instruction that need to be placed in cfg nodes of the parent*)
   ; initd_exps: Exp.t list  (** list of expressions that are initialised by the instructions *) }
 
+val pp_control : F.formatter -> control -> unit
+
 (** A translation result. It is returned by the translation function. *)
 type trans_result =
   { control: control