src/Pure/Admin/build_log.scala
author wenzelm
Tue Oct 18 14:32:51 2016 +0200 (2016-10-18)
changeset 64300 3073688abbe9
parent 64299 4f11063c6e55
child 64303 605351c7ef97
permissions -rw-r--r--
clarified multiple props: result needs to fit on a single line within the log file;
     1 /*  Title:      Pure/Admin/build_log.scala
     2     Author:     Makarius
     3 
     4 Build log parsing for current and historic formats.
     5 */
     6 
     7 package isabelle
     8 
     9 
    10 import java.io.{File => JFile}
    11 import java.time.ZoneId
    12 import java.time.format.{DateTimeFormatter, DateTimeParseException}
    13 import java.util.Locale
    14 
    15 import scala.collection.mutable
    16 import scala.util.matching.Regex
    17 
    18 
    19 object Build_Log
    20 {
    21   /** content **/
    22 
    23   /* properties */
    24 
    25   object Prop
    26   {
    27     def multiple(name: String, args: List[String]): Properties.T =
    28       if (args.isEmpty) Nil
    29       else List(name -> YXML.string_of_body(XML.Encode.list(XML.Encode.string)(args)))
    30 
    31     val build_tags = "build_tags"  // multiple
    32     val build_args = "build_args"  // multiple
    33     val build_group_id = "build_group_id"
    34     val build_id = "build_id"
    35     val build_engine = "build_engine"
    36     val build_host = "build_host"
    37     val build_start = "build_start"
    38     val build_end = "build_end"
    39     val isabelle_version = "isabelle_version"
    40     val afp_version = "afp_version"
    41   }
    42 
    43 
    44   /* settings */
    45 
    46   object Settings
    47   {
    48     val build_settings = List("ISABELLE_BUILD_OPTIONS")
    49     val ml_settings = List("ML_PLATFORM", "ML_HOME", "ML_SYSTEM", "ML_OPTIONS")
    50     val all_settings = build_settings ::: ml_settings
    51 
    52     type Entry = (String, String)
    53     type T = List[Entry]
    54 
    55     object Entry
    56     {
    57       def unapply(s: String): Option[Entry] =
    58         s.indexOf('=') match {
    59           case -1 => None
    60           case i =>
    61             val a = s.substring(0, i)
    62             val b = Library.perhaps_unquote(s.substring(i + 1))
    63             Some((a, b))
    64         }
    65       def apply(a: String, b: String): String = a + "=" + quote(b)
    66       def getenv(a: String): String = apply(a, Isabelle_System.getenv(a))
    67     }
    68 
    69     def show(): String =
    70       cat_lines(
    71         build_settings.map(Entry.getenv(_)) ::: List("") ::: ml_settings.map(Entry.getenv(_)))
    72   }
    73 
    74 
    75   /* file names */
    76 
    77   def log_date(date: Date): String =
    78     String.format(Locale.ROOT, "%s.%05d",
    79       DateTimeFormatter.ofPattern("yyyy-MM-dd").format(date.rep),
    80       new java.lang.Long((date.time - date.midnight.time).ms / 1000))
    81 
    82   def log_subdir(date: Date): Path =
    83     Path.explode("log") + Path.explode(date.rep.getYear.toString)
    84 
    85   def log_filename(engine: String, date: Date, more: List[String] = Nil): Path =
    86     Path.explode((engine :: log_date(date) :: more).mkString("", "_", ".log"))
    87 
    88 
    89   /* log file collections */
    90 
    91   def is_log(file: JFile): Boolean =
    92     List(".log", ".log.gz", ".log.xz").exists(ext => file.getName.endsWith(ext))
    93 
    94   def isatest_files(dir: Path): List[JFile] =
    95     File.find_files(dir.file, file => is_log(file) && file.getName.startsWith("isatest-makeall-"))
    96 
    97   def afp_test_files(dir: Path): List[JFile] =
    98     File.find_files(dir.file, file => is_log(file) && file.getName.startsWith("afp-test-devel-"))
    99 
   100 
   101 
   102   /** log file **/
   103 
   104   def print_date(date: Date): String = Log_File.Date_Format(date)
   105 
   106   object Log_File
   107   {
   108     def apply(name: String, lines: List[String]): Log_File =
   109       new Log_File(name, lines)
   110 
   111     def apply(name: String, text: String): Log_File =
   112       Log_File(name, Library.trim_split_lines(text))
   113 
   114     def apply(file: JFile): Log_File =
   115     {
   116       val name = file.getName
   117       val (base_name, text) =
   118         Library.try_unsuffix(".gz", name) match {
   119           case Some(base_name) => (base_name, File.read_gzip(file))
   120           case None =>
   121             Library.try_unsuffix(".xz", name) match {
   122               case Some(base_name) => (base_name, File.read_xz(file))
   123               case None => (name, File.read(file))
   124             }
   125           }
   126       apply(base_name, text)
   127     }
   128 
   129     def apply(path: Path): Log_File = apply(path.file)
   130 
   131 
   132     /* date format */
   133 
   134     val Date_Format =
   135     {
   136       val fmts =
   137         Date.Formatter.variants(
   138           List("EEE MMM d HH:mm:ss O yyyy", "EEE MMM d HH:mm:ss VV yyyy"),
   139           List(Locale.ENGLISH, Locale.GERMAN)) :::
   140         List(
   141           DateTimeFormatter.RFC_1123_DATE_TIME,
   142           Date.Formatter.pattern("EEE MMM d HH:mm:ss yyyy").withZone(ZoneId.of("Europe/Berlin")))
   143 
   144       def tune_timezone(s: String): String =
   145         s match {
   146           case "CET" | "MET" => "GMT+1"
   147           case "CEST" | "MEST" => "GMT+2"
   148           case "EST" => "Europe/Berlin"
   149           case _ => s
   150         }
   151       def tune_weekday(s: String): String =
   152         s match {
   153           case "Die" => "Di"
   154           case "Mit" => "Mi"
   155           case "Don" => "Do"
   156           case "Fre" => "Fr"
   157           case "Sam" => "Sa"
   158           case "Son" => "So"
   159           case _ => s
   160         }
   161 
   162       def tune(s: String): String =
   163         Word.implode(
   164           Word.explode(s) match {
   165             case a :: "M\uFFFDr" :: bs => tune_weekday(a) :: "Mär" :: bs.map(tune_timezone(_))
   166             case a :: bs => tune_weekday(a) :: bs.map(tune_timezone(_))
   167             case Nil => Nil
   168           }
   169         )
   170 
   171       Date.Format.make(fmts, tune)
   172     }
   173 
   174 
   175     /* inlined content */
   176 
   177     def print_props(marker: String, props: Properties.T): String =
   178       marker + YXML.string_of_body(XML.Encode.properties(props))
   179   }
   180 
   181   class Log_File private(val name: String, val lines: List[String])
   182   {
   183     log_file =>
   184 
   185     override def toString: String = name
   186 
   187     def text: String = cat_lines(lines)
   188 
   189     def err(msg: String): Nothing =
   190       error("Error in log file " + quote(name) + ": " + msg)
   191 
   192 
   193     /* date format */
   194 
   195     object Strict_Date
   196     {
   197       def unapply(s: String): Some[Date] =
   198         try { Some(Log_File.Date_Format.parse(s)) }
   199         catch { case exn: DateTimeParseException => log_file.err(exn.getMessage) }
   200     }
   201 
   202 
   203     /* inlined content */
   204 
   205     def find[A](f: String => Option[A]): Option[A] =
   206       lines.iterator.map(f).find(_.isDefined).map(_.get)
   207 
   208     def find_line(marker: String): Option[String] =
   209       find(Library.try_unprefix(marker, _))
   210 
   211     def find_match(regex: Regex): Option[String] =
   212       lines.iterator.map(regex.unapplySeq(_)).find(res => res.isDefined && res.get.length == 1).
   213         map(res => res.get.head)
   214 
   215 
   216     /* settings */
   217 
   218     def get_setting(a: String): Option[Settings.Entry] =
   219       lines.find(_.startsWith(a + "=")) match {
   220         case Some(line) => Settings.Entry.unapply(line)
   221         case None => None
   222       }
   223 
   224     def get_settings(as: List[String]): Settings.T =
   225       for { a <- as; entry <- get_setting(a) } yield entry
   226 
   227 
   228     /* properties (YXML) */
   229 
   230     val xml_cache = new XML.Cache()
   231 
   232     def parse_props(text: String): Properties.T =
   233       xml_cache.props(XML.Decode.properties(YXML.parse_body(text)))
   234 
   235     def filter_props(marker: String): List[Properties.T] =
   236       for {
   237         line <- lines
   238         s <- Library.try_unprefix(marker, line)
   239         if YXML.detect(s)
   240       } yield parse_props(s)
   241 
   242     def find_props(marker: String): Option[Properties.T] =
   243       find_line(marker) match {
   244         case Some(text) if YXML.detect(text) => Some(parse_props(text))
   245         case _ => None
   246       }
   247 
   248 
   249     /* parse various formats */
   250 
   251     def parse_meta_info(): Meta_Info = Build_Log.parse_meta_info(log_file)
   252 
   253     def parse_build_info(): Build_Info = Build_Log.parse_build_info(log_file)
   254 
   255     def parse_session_info(
   256         default_name: String = "",
   257         command_timings: Boolean = false,
   258         ml_statistics: Boolean = false,
   259         task_statistics: Boolean = false): Session_Info =
   260       Build_Log.parse_session_info(
   261         log_file, default_name, command_timings, ml_statistics, task_statistics)
   262   }
   263 
   264 
   265 
   266   /** meta info **/
   267 
   268   object Meta_Info
   269   {
   270     val empty: Meta_Info = Meta_Info(Nil, Nil)
   271   }
   272 
   273   sealed case class Meta_Info(props: Properties.T, settings: List[(String, String)])
   274   {
   275     def is_empty: Boolean = props.isEmpty && settings.isEmpty
   276   }
   277 
   278   object Isatest
   279   {
   280     val engine = "isatest"
   281     val Start = new Regex("""^------------------- starting test --- (.+) --- (.+)$""")
   282     val End = new Regex("""^------------------- test (?:successful|FAILED) --- (.+) --- .*$""")
   283     val Isabelle_Version = new Regex("""^Isabelle version: (\S+)$""")
   284     val No_AFP_Version = new Regex("""$.""")
   285   }
   286 
   287   object AFP_Test
   288   {
   289     val engine = "afp-test"
   290     val Start = new Regex("""^Start test(?: for .+)? at ([^,]+), (.*)$""")
   291     val Start_Old = new Regex("""^Start test(?: for .+)? at ([^,]+)$""")
   292     val End = new Regex("""^End test on (.+), .+, elapsed time:.*$""")
   293     val Isabelle_Version = new Regex("""^Isabelle version: .* -- hg id (\S+)$""")
   294     val AFP_Version = new Regex("""^AFP version: .* -- hg id (\S+)$""")
   295     val Bad_Init = new Regex("""^cp:.*: Disc quota exceeded$""")
   296   }
   297 
   298   object Jenkins
   299   {
   300     val engine = "jenkins"
   301     val Start = new Regex("""^Started .*$""")
   302     val Start_Date = new Regex("""^Build started at (.+)$""")
   303     val No_End = new Regex("""$.""")
   304     val Isabelle_Version = new Regex("""^Isabelle id (\S+)$""")
   305     val AFP_Version = new Regex("""^AFP id (\S+)$""")
   306     val CONFIGURATION = "=== CONFIGURATION ==="
   307     val BUILD = "=== BUILD ==="
   308     val FINISHED = "Finished: "
   309   }
   310 
   311   private def parse_meta_info(log_file: Log_File): Meta_Info =
   312   {
   313     def parse(engine: String, host: String, start: Date,
   314       End: Regex, Isabelle_Version: Regex, AFP_Version: Regex): Meta_Info =
   315     {
   316       val build_id =
   317       {
   318         val prefix = if (host != "") host else if (engine != "") engine else ""
   319         (if (prefix == "") "build" else prefix) + ":" + start.time.ms
   320       }
   321       val build_engine = if (engine == "") Nil else List(Prop.build_engine -> engine)
   322       val build_host = if (host == "") Nil else List(Prop.build_host -> host)
   323 
   324       val start_date = List(Prop.build_start -> start.toString)
   325       val end_date =
   326         log_file.lines.last match {
   327           case End(log_file.Strict_Date(end_date)) =>
   328             List(Prop.build_end -> end_date.toString)
   329           case _ => Nil
   330         }
   331 
   332       val isabelle_version =
   333         log_file.find_match(Isabelle_Version).map(Prop.isabelle_version -> _)
   334       val afp_version =
   335         log_file.find_match(AFP_Version).map(Prop.afp_version -> _)
   336 
   337       Meta_Info((Prop.build_id -> build_id) :: build_engine ::: build_host :::
   338           start_date ::: end_date ::: isabelle_version.toList ::: afp_version.toList,
   339         log_file.get_settings(Settings.all_settings))
   340     }
   341 
   342     log_file.lines match {
   343       case line :: _ if line.startsWith(Build_History.META_INFO_MARKER) =>
   344         Meta_Info(log_file.find_props(Build_History.META_INFO_MARKER).get,
   345           log_file.get_settings(Settings.all_settings))
   346 
   347       case Isatest.Start(log_file.Strict_Date(start), host) :: _ =>
   348         parse(Isatest.engine, host, start, Isatest.End,
   349           Isatest.Isabelle_Version, Isatest.No_AFP_Version)
   350 
   351       case AFP_Test.Start(log_file.Strict_Date(start), host) :: _ =>
   352         parse(AFP_Test.engine, host, start, AFP_Test.End,
   353           AFP_Test.Isabelle_Version, AFP_Test.AFP_Version)
   354 
   355       case AFP_Test.Start_Old(log_file.Strict_Date(start)) :: _ =>
   356         parse(AFP_Test.engine, "", start, AFP_Test.End,
   357           AFP_Test.Isabelle_Version, AFP_Test.AFP_Version)
   358 
   359       case Jenkins.Start() :: _
   360       if log_file.lines.contains(Jenkins.CONFIGURATION) ||
   361          log_file.lines.last.startsWith(Jenkins.FINISHED) =>
   362         log_file.lines.dropWhile(_ != Jenkins.BUILD) match {
   363           case Jenkins.BUILD :: _ :: Jenkins.Start_Date(log_file.Strict_Date(start)) :: _ =>
   364             parse(Jenkins.engine, "", start.to(ZoneId.of("Europe/Berlin")), Jenkins.No_End,
   365               Jenkins.Isabelle_Version, Jenkins.AFP_Version)
   366           case _ => Meta_Info.empty
   367         }
   368 
   369       case line :: _ if line.startsWith("\0") => Meta_Info.empty
   370       case List(Isatest.End(_)) => Meta_Info.empty
   371       case _ :: AFP_Test.Bad_Init() :: _ => Meta_Info.empty
   372       case Nil => Meta_Info.empty
   373 
   374       case _ => log_file.err("cannot detect log file format")
   375     }
   376   }
   377 
   378 
   379 
   380   /** build info: produced by isabelle build or build_history **/
   381 
   382   val ML_STATISTICS_MARKER = "\fML_statistics = "
   383   val SESSION_NAME = "session_name"
   384 
   385   object Session_Status extends Enumeration
   386   {
   387     val EXISTING = Value("existing")
   388     val FINISHED = Value("finished")
   389     val FAILED = Value("failed")
   390     val CANCELLED = Value("cancelled")
   391   }
   392 
   393   sealed case class Session_Entry(
   394     chapter: String,
   395     groups: List[String],
   396     threads: Option[Int],
   397     timing: Timing,
   398     ml_timing: Timing,
   399     ml_statistics: List[Properties.T],
   400     heap_size: Option[Long],
   401     status: Session_Status.Value)
   402   {
   403     def finished: Boolean = status == Session_Status.FINISHED
   404   }
   405 
   406   sealed case class Build_Info(sessions: Map[String, Session_Entry])
   407   {
   408     def session(name: String): Session_Entry = sessions(name)
   409     def get_session(name: String): Option[Session_Entry] = sessions.get(name)
   410 
   411     def get_default[A](name: String, f: Session_Entry => A, x: A): A =
   412       get_session(name) match {
   413         case Some(entry) => f(entry)
   414         case None => x
   415       }
   416 
   417     def finished_sessions: List[String] = sessions.keySet.iterator.filter(finished(_)).toList
   418     def finished(name: String): Boolean = get_default(name, _.finished, false)
   419     def timing(name: String): Timing = get_default(name, _.timing, Timing.zero)
   420     def ml_timing(name: String): Timing = get_default(name, _.ml_timing, Timing.zero)
   421   }
   422 
   423   private def parse_build_info(log_file: Log_File): Build_Info =
   424   {
   425     object Chapter_Name
   426     {
   427       def unapply(s: String): Some[(String, String)] =
   428         space_explode('/', s) match {
   429           case List(chapter, name) => Some((chapter, name))
   430           case _ => Some(("", s))
   431         }
   432     }
   433 
   434     val Session_No_Groups = new Regex("""^Session (\S+)$""")
   435     val Session_Groups = new Regex("""^Session (\S+) \((.*)\)$""")
   436     val Session_Finished1 =
   437       new Regex("""^Finished (\S+) \((\d+):(\d+):(\d+) elapsed time, (\d+):(\d+):(\d+) cpu time.*$""")
   438     val Session_Finished2 =
   439       new Regex("""^Finished (\S+) \((\d+):(\d+):(\d+) elapsed time.*$""")
   440     val Session_Timing =
   441       new Regex("""^Timing (\S+) \((\d) threads, (\d+\.\d+)s elapsed time, (\d+\.\d+)s cpu time, (\d+\.\d+)s GC time.*$""")
   442     val Session_Started = new Regex("""^(?:Running|Building) (\S+) \.\.\.$""")
   443     val Session_Failed = new Regex("""^(\S+) FAILED""")
   444     val Session_Cancelled = new Regex("""^(\S+) CANCELLED""")
   445     val Heap = new Regex("""^Heap (\S+) \((\d+) bytes\)$""")
   446 
   447     var chapter = Map.empty[String, String]
   448     var groups = Map.empty[String, List[String]]
   449     var threads = Map.empty[String, Int]
   450     var timing = Map.empty[String, Timing]
   451     var ml_timing = Map.empty[String, Timing]
   452     var started = Set.empty[String]
   453     var failed = Set.empty[String]
   454     var cancelled = Set.empty[String]
   455     var ml_statistics = Map.empty[String, List[Properties.T]]
   456     var heap_sizes = Map.empty[String, Long]
   457 
   458     def all_sessions: Set[String] =
   459       chapter.keySet ++ groups.keySet ++ threads.keySet ++ timing.keySet ++ ml_timing.keySet ++
   460       failed ++ cancelled ++ started ++ ml_statistics.keySet ++ heap_sizes.keySet
   461 
   462 
   463     for (line <- log_file.lines) {
   464       line match {
   465         case Session_No_Groups(Chapter_Name(chapt, name)) =>
   466           chapter += (name -> chapt)
   467           groups += (name -> Nil)
   468 
   469         case Session_Groups(Chapter_Name(chapt, name), grps) =>
   470           chapter += (name -> chapt)
   471           groups += (name -> Word.explode(grps))
   472 
   473         case Session_Started(name) =>
   474           started += name
   475 
   476         case Session_Finished1(name,
   477             Value.Int(e1), Value.Int(e2), Value.Int(e3),
   478             Value.Int(c1), Value.Int(c2), Value.Int(c3)) =>
   479           val elapsed = Time.hms(e1, e2, e3)
   480           val cpu = Time.hms(c1, c2, c3)
   481           timing += (name -> Timing(elapsed, cpu, Time.zero))
   482 
   483         case Session_Finished2(name,
   484             Value.Int(e1), Value.Int(e2), Value.Int(e3)) =>
   485           val elapsed = Time.hms(e1, e2, e3)
   486           timing += (name -> Timing(elapsed, Time.zero, Time.zero))
   487 
   488         case Session_Timing(name,
   489             Value.Int(t), Value.Double(e), Value.Double(c), Value.Double(g)) =>
   490           val elapsed = Time.seconds(e)
   491           val cpu = Time.seconds(c)
   492           val gc = Time.seconds(g)
   493           ml_timing += (name -> Timing(elapsed, cpu, gc))
   494           threads += (name -> t)
   495 
   496         case Heap(name, Value.Long(size)) =>
   497           heap_sizes += (name -> size)
   498 
   499         case _ if line.startsWith(ML_STATISTICS_MARKER) =>
   500           val (name, props) =
   501             Library.try_unprefix(ML_STATISTICS_MARKER, line).map(log_file.parse_props(_)) match {
   502               case Some((SESSION_NAME, session_name) :: props) => (session_name, props)
   503               case _ => log_file.err("malformed ML_statistics " + quote(line))
   504             }
   505           ml_statistics += (name -> (props :: ml_statistics.getOrElse(name, Nil)))
   506 
   507         case _ =>
   508       }
   509     }
   510 
   511     val sessions =
   512       Map(
   513         (for (name <- all_sessions.toList) yield {
   514           val status =
   515             if (failed(name)) Session_Status.FAILED
   516             else if (cancelled(name)) Session_Status.CANCELLED
   517             else if (timing.isDefinedAt(name) || ml_timing.isDefinedAt(name))
   518               Session_Status.FINISHED
   519             else if (started(name)) Session_Status.FAILED
   520             else Session_Status.EXISTING
   521           val entry =
   522             Session_Entry(
   523               chapter.getOrElse(name, ""),
   524               groups.getOrElse(name, Nil),
   525               threads.get(name),
   526               timing.getOrElse(name, Timing.zero),
   527               ml_timing.getOrElse(name, Timing.zero),
   528               ml_statistics.getOrElse(name, Nil).reverse,
   529               heap_sizes.get(name),
   530               status)
   531           (name -> entry)
   532         }):_*)
   533     Build_Info(sessions)
   534   }
   535 
   536 
   537 
   538   /** session info: produced by "isabelle build" **/
   539 
   540   sealed case class Session_Info(
   541     session_name: String,
   542     session_timing: Properties.T,
   543     command_timings: List[Properties.T],
   544     ml_statistics: List[Properties.T],
   545     task_statistics: List[Properties.T])
   546 
   547   private def parse_session_info(
   548     log_file: Log_File,
   549     default_name: String,
   550     command_timings: Boolean,
   551     ml_statistics: Boolean,
   552     task_statistics: Boolean): Session_Info =
   553   {
   554     val xml_cache = new XML.Cache()
   555 
   556     val session_name =
   557       log_file.find_line("\fSession.name = ") match {
   558         case None => default_name
   559         case Some(name) if default_name == "" || default_name == name => name
   560         case Some(name) => log_file.err("log from different session " + quote(name))
   561       }
   562     val session_timing = log_file.find_props("\fTiming = ") getOrElse Nil
   563     val command_timings_ =
   564       if (command_timings) log_file.filter_props("\fcommand_timing = ") else Nil
   565     val ml_statistics_ =
   566       if (ml_statistics) log_file.filter_props(ML_STATISTICS_MARKER) else Nil
   567     val task_statistics_ =
   568       if (task_statistics) log_file.filter_props("\ftask_statistics = ") else Nil
   569 
   570     Session_Info(session_name, session_timing, command_timings_, ml_statistics_, task_statistics_)
   571   }
   572 }