dcp_inspect

#!/usr/bin/env ruby
# encoding: utf-8
#
# dcp_inspect checks and validates DCPs (Digital Cinema Packages)
#
# 2011-2023 Wolfgang Woehl
#
# This program is free software: you can redistribute it and/or modify
# it under the terms of the GNU General Public License as published by
# the Free Software Foundation, either version 3 of the License, or
# (at your option) any later version.
#
# This program is distributed in the hope that it will be useful,
# but WITHOUT ANY WARRANTY; without even the implied warranty of
# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
# GNU General Public License for more details.
#
# You should have received a copy of the GNU General Public License
# along with this program.  If not, see <http://www.gnu.org/licenses/>.
#
AppName = File.basename( $0 )
AppVersion = 'v1.2024.01.01'
AppStartSeconds = Time.now
#
# dcp_inspect is a tool for deep inspection and validation of digital
# cinema packages (DCP). This includes integrity checks, asset inspection,
# schema validation, signature and certificate verification and
# composition summaries
#
# Usage:
#
#   dcp_inspect --help
#   dcp_inspect /path/to/dir
#
# Installation:
#
#   See https://github.com/wolfgangw/digital_cinema_tools_distribution/wiki
#   for an easy-to-use setup script. This will install everything required.
#
# Features:
#
# - Will find and check all DCPs in a filesystem tree
#
# - Runs schema validation on all infrastructure files and DCSubtitle.
#   Validation errors will be reported but dcp_inspect will still try to
#   inspect the contents of non-valid files.
#
# - Checks and verifies signatures
#
# - Reports detailed composition information
#
# - Deep-inspects compositions. This includes composition type consistency
#   and completeness checks. dcp_inspect goes through some lengths to determine
#   a composition's type (SMPTE/Interop).
#
# - Checks presence and sanity of DCSubtitle resources
#
# - Reports in detail all errors encountered
#
# See [Examples](https://github.com/wolfgangw/backports/wiki/Example-output-from-dcp_inspect).
#
# Manual installation / Requirements:
#
#   If you prefer manual installation you will need the following:
#
#  - $ git clone git://github.com/wolfgangw/backports.git
#  - asdcplib and its cli tools (http://www.cinecert.com/asdcplib/)
#  - Nokogiri, a ruby wrapper for libxml2 (gem install nokogiri)
#  - dcp_inspect requires xsd/ next to it.
#
#   Run
#     $ git pull
#   in backports to keep up-to-date.
#
#
# Thanks to the Nokogiri team. You're a wicked crew.
# Thanks to Julik for his Timecode library.
#   https://github.com/guerilla-di/timecode
# Thanks to Mattias Mattsson for DCSubtitle.v1.mattsson.xsd and
#   great feedback from Göteborg International Film Festival.
# Thanks to Mike Radford and Tammo Buhren for test materials.
# Thanks to Alexis Michaltsis for interesting test cases and feedback.
# Thanks to Lilian Lefranc for constant feedback and a donation
#   which clearly exceeded what can safely be called a gesture.
#   Appreciated and you rock.
# Thanks to Adrianne Jorge for a great user report from Sundance and Sarasota.
# Thanks to Terrence Meiczinger.
# 

# ruby version and platform
RubyVersionPlatform = [ RUBY_ENGINE, RUBY_VERSION, RUBY_PLATFORM ].join( ' ' )

# Exit codes
DCP_OK = 0
DCP_ERROR = 1
NO_ARG = 2
TOO_MANY_ARGS = 3
ARG_NOT_A_DIR = 4
XML_CATALOG_NOT_FOUND = 5
XSD_STORE_NOT_FOUND = 6
BAD_HASH_LIMIT_ARG = 7
LOGFILE_WRITE_ERROR = 8
FILE_ACCESS_ERROR = 9
LOGFILE_EXISTS_ERROR = 10
GEM_LOAD_ERROR = 11
REQUIRED_COMMAND_NOT_FOUND = 12
ENV_DCP_INSPECT_DIR_NOT_SET = 13
DCP_INSPECT_DIR_NOT_WRITABLE = 14
AUTOLOGFILE_WRITE_ERROR = 15
MKFIFO_FAIL = 16
RMFIFO_FAIL = 17
USER_INTERRUPT = 18
RUBY_VERSION_NOT_SUPPORTED = 19
RUBY_TYPE_ERROR = 20
RUBY_EXCEPTION = 21
GRACEFUL_SHUTDOWN = 22
LIB_LOAD_ERROR = 23
RUBY_NAME_ERROR = 24
RUBY_ARGUMENT_ERROR = 25

# Constants
PictureBitrateMaxDCI = 250.0 # Mb/s
PictureBitrateMaxDCISafetyMargin = 2.0 # percent
PictureBitrateMaxDCISafe = ( PictureBitrateMaxDCI / 100 * ( 100 - PictureBitrateMaxDCISafetyMargin ) ).round( 2 )
PictureBitrateMaxHFR = 400.0 # Mb/s

# Required libs
required_libs = [
  'optparse',
  'ostruct',
  'pathname',
  'shellwords',
  'openssl',
  'stringio',
  'fileutils',
  'open3',
]
if RUBY_VERSION < '3.4'
  required_libs << 'base64'
end
missing_libs = []
required_libs.each do |lib|
  begin
    require lib
  rescue LoadError => e
    puts e.inspect
    missing_libs << lib
  end
end
if missing_libs.any?
  puts "Ruby installation (#{ RubyVersionPlatform }) is missing required libraries (#{ missing_libs.join( ', ' ) })"
  exit LIB_LOAD_ERROR
end
# Required gems
required_gems = [
  'nokogiri',
  'ttfunk',
]
if RUBY_VERSION >= '3.4'
  required_gems << 'base64'
end
missing_gems = []
required_gems.each do |gem|
  begin
    require gem
  rescue LoadError => e
    puts e.inspect
    missing_gems << gem
  end
end
if missing_gems.any?
  puts "Please run 'gem install #{ missing_gems.join( ' ' ) }' (without the quotes) and try again"
  exit GEM_LOAD_ERROR
end

# lib/options.rb
class Options
  def self.parse( args )
    # defaults
    options = OpenStruct.new
    options.check_hashes = true
    options.check_hashes_limit = :no_limit
    options.image_analysis = false # not yet implemented
    options.audio_analysis = true
    options.validate = true
    options.as_asset_store = false
    options.verbosity = [ 'debug', 'dev' ]
    options.logfile = nil
    options.logfile_append = nil
    options.logfile_autolog = nil
    options.overwrite_logfile = false
    options.verbosity_choices = [ 'quiet', 'dev', 'errors', 'hints', 'info', 'cpl', 'debug', 'trace_func' ]

    opts = OptionParser.new do |opts|
      opts.banner = <<BANNER
#{ AppName } #{ AppVersion }
Usage: #{ AppName } [options] <path>
 
BANNER
      opts.on( '--nh', '--no-hash', 'No asset hash checks' ) do
        options.check_hashes = false
      end
      opts.on( '--hl', '--hash-limit limit', String, 'Limit asset hash checks to assets smaller than limit. E.g. 700KB, 50MB or 1GB (Default: No limit)' ) do |p|
        options.check_hashes_limit = p.downcase
      end
      opts.on( '--ni', '--no-image-analysis', 'No image analysis (Image analysis not yet implemented)' ) do
        options.image_analysis = false
      end
      opts.on( '--na', '--no-audio-analysis', 'No audio analysis' ) do
        options.audio_analysis = false
      end
      opts.on( '--no-schema', 'Skip schema checks' ) do
        options.validate = false
      end
      opts.on( '-s', '--as-asset-store', 'Simulate asset store by merging all collected AM dictionaries' ) do
        options.as_asset_store = true
      end
      opts.on( '-l', '--logfile path', String, 'Write full report to logfile at path' ) do |p|
        options.logfile = p
      end
      opts.on( '--la', '--logfile-append path', String, 'Append full report to logfile at path' ) do |p|
        options.logfile_append = p
      end
      opts.on( '--autolog', "Write full report to $DCP_INSPECT_DIR. (Default: Don't)" ) do
        options.logfile_autolog = true
      end
      opts.on( '-L', '--overwrite-logfile', 'Overwrite logfile (Default: Do not overwrite if logfile exists)' ) do
        options.overwrite_logfile = true
      end
      opts.on( '-v', '--verbosity cutout', Array, "Use quiet, errors, hints, info, debug or cpl. Specify multiple cutouts like '-v errors,info' (Default: debug)" ) do |p|
        options.verbosity = [] # option was given so reset
        p.each do |e|
          if options.verbosity_choices.include?( e )
            options.verbosity << e
          end
        end
        if options.verbosity.empty?
          options.verbosity = [ 'debug' ]
        end
      end
      opts.on_tail( '-h', '--help', 'Display this screen' ) do
        puts opts
        exit
      end
    end

    begin
      opts.parse!( args )
    rescue Exception => e
      exit if e.class == SystemExit
      puts "Options error: #{ e.message }"
      exit
    end
    options
  end # parse
end # Options


# * lib/logger.rb
class DLogger
  attr_reader :is_quiet, :prints_dev, :prints_errors, :prints_hints, :prints_info, :prints_debug, :prints_cr, :prints_cpl, :writes_logfile, :logfile, :writes_autolog
  def initialize( prefix, options )
    @prefix = prefix
    @full_log = ( options.logfile || options.logfile_autolog || options.logfile_append ? Array.new : nil )

    @dev, @errors, @hints, @info, @debug, @cr, @cpl = [ false, false, false, false, false, false, false ]
    options.verbosity.each do |cutout|
      case cutout
      when 'quiet'  then @is_quiet = true; break
      when 'debug'  then @dev, @errors, @hints, @info, @debug, @cr, @cpl = [ false, true, true, true, true, true, true ]; @is_quiet = false; break
      when 'dev'    then @dev, @errors, @hints, @info, @debug, @cr, @cpl = [ true, true, true, true, true, true, true ]; @is_quiet = false; break
      when 'errors' then @errors = true
      when 'hints'  then @hints = true
      when 'info'   then @info = true
      when 'cpl'    then @cpl = true
      when 'trace_func'
        @dev, @errors, @hints, @info, @debug, @cr, @cpl = [ true, false, false, false, false, false, false ]; @is_quiet = false
        set_trace_func proc { |event, file, line, id, binding, classname|
          printf "%8s %s:%-2d %10s %8s\n", event, file, line, id, classname
        }
      end
    end

    @writes_logfile = true if options.logfile
    @writes_autolog = true if options.logfile_autolog
    @logfile = options.logfile
    @prints_dev, @prints_errors, @prints_hints, @prints_info, @prints_debug, @prints_cr, @prints_cpl = @dev, @errors, @hints, @info, @debug, @cr, @cpl
    @color = Hash.new
    @color[ :dev ] = '32' # green
  end
  def dev( text )
    if @dev then outbound_colored( text, @color[ :dev ] ) end
  end
  def errors( text )
    if @errors then outbound( text ) end
  end
  def hints( text )
    if @hints then outbound( text ) end
  end
  def info( text )
    if @info then outbound( text ) end
  end
  def debug( text )
    if @debug then outbound( text ) end
  end
  def cpl( text )
    if @cpl then outbound( text ) end
  end
  def cr( text )
    # don't go to @full_log here
    carriage_return( text ) if @cr
  end
  def outbound( text )
    printf "%s %s\n", @prefix, text
    @full_log << text if @full_log
  end
  def outbound_colored( text, color )
    printf "%s %s\n", @prefix, colored( text, color )
  end
  def colored( text, color )
    "\033[#{ color }m#{ text }\033[0m"
  end
  def to_console( text ) printf "%s %s\n", @prefix, text end
  def carriage_return( text ) printf "%s %s\r", @prefix, text end
  def full_log_blob
    @full_log.join( "\n" ) + "\n"
  end
end


# Workaround Nokogiri::XML::Document#collect_namespaces peculiarity
# (see https://github.com/sparklemotion/nokogiri/issues/885 for details)
#
# collect_all_namespaces_href_keys will return
#
#   {
#     "http://www.w3.org/XML/1998/namespace"              =>  ["xml"],
#     "http://www.smpte-ra.org/schemas/429-7/2006/CPL"    =>  [nil],
#     "http://isdcf.com/schemas/draft/2011/cpl-metadata"  =>  ["meta"],
#     "http://www.w3.org/2000/09/xmldsig#"                =>  [nil]
#   }
#
# where nil implies xmlns.
# This is an example where multiple default namespace definitions exist
# and are used in different document fragments.
#
# collect_all_namespaces_prefix_keys will return
#
#   {
#     "xml"   =>  ["http://www.w3.org/XML/1998/namespace"],
#     "nil"   =>  ["http://www.smpte-ra.org/schemas/429-7/2006/CPL", "http://www.w3.org/2000/09/xmldsig#"],
#     "meta"  =>  ["http://isdcf.com/schemas/draft/2011/cpl-metadata"]
#   }
#
class Nokogiri::XML::Document
  def collect_all_namespaces_href_keys
    xpath( "//namespace::*" ).inject( {} ) do |hash, ns|
      ( hash[ ns.href ] ||= [] ) << ns.prefix unless ( hash[ ns.href ] and hash[ ns.href ].include? ns.prefix )
      hash
    end
  end
  def collect_all_namespaces_prefix_keys
    xpath( "//namespace::*" ).inject( {} ) do |hash, ns|
      ( hash[ ns.prefix ] ||= [] ) << ns.href unless ( hash[ ns.prefix ] and hash[ ns.prefix ].include? ns.href )
      hash
    end
  end
end


# lib/mxf.rb
module MxfTools
  def asdcplib_version
    out, err, status = Open3.capture3( 'asdcp-unwrap -V' )
    major, minor, patchlevel = out.scan( /(\d)\.(\d+)\.(\d+)/ )[0].map { |e| e.to_i }
  end

  def asdcplib_version_supported?
    major, minor, patchlevel = asdcplib_version
    case major
    when 1
      true
    else
      false
    end
  end

  def mxf_inspect( filename )
    errors_present = false
    out, err, status = Shell.asdcp_mxf_info( filename )
    if err =~ /EditRate and SampleRate do not match/ and err =~ /File may contain JPEG Interop stereoscopic images/
      # With 1.12.58 this is not required anymore. Keep it for backwards compat
      out, err, status = Shell.asdcp_mxf_interop_stereoscopic_info( filename )
    end

    if out.empty?
      return nil
    elsif err =~ /Program stopped on error/
      if err =~ /SeekToRIP failed/
        return nil
      elsif err =~ /File open failure/
        return nil
      elsif out =~ /essence type is/
        # See e.g. Fox Format Test 2D-2k-50 (scope v1.0) (CPL 3452c9ed, MXF 20f97e4e)
        errors_present = true
      end
    end

    out = out.split( /\n\s*/ ).collect { |line| line.split( ': ' ) }
    et = [ 'EssenceType',
           case out.first.to_s
           when /#{ MStr::Stereoscopic_pictures }/
             MStr::Stereoscopic_pictures
           when /#{ MStr::Pictures }/
             MStr::Pictures
           when /#{ MStr::Mpeg2 }/
             MStr::Mpeg2
           when /#{ MStr::Audio }/
             MStr::Audio
           when /#{ MStr::Atmos }/
             MStr::Atmos
           when /#{ MStr::Timed_text }/i
             MStr::Timed_text
           else
             nil
           end
    ]
    return Hash[ out << et ]
  end
end # MxfTools
include MxfTools


class Pipe
  def initialize
    @pipename = "#{ AppName }_#{ rand( 2 ** 32 ).to_s( 16 ) }"
    @pipe = nil
    result = make_pipe
  end
  def remove
    out, err, status = Open3.capture3( "rm #{ self.path }" )
  end
  def path
    "/tmp/#{ @pipename }"
  end
  private
  def make_pipe
    out, err, status = Open3.capture3( "mkfifo #{ self.path }" )
    @pipe = self.path
  end
end # Pipe


def bars( list )
  level = '█▇▆▅▄▃▂▁'
  '|' + list.inject( [] ) do |ary, value|
    case value
    when '-inf'
      ary << '.'
    else
      case value.to_f.abs
      when 0.0
        level_index = level[ 0 ]
      else
        level_index = [ 0, ( Math.log2 value.to_f.abs ).to_i.abs, level.size - 1 ].sort[ 1 ] # clamp between 0 and level.size - 1
      end
      ary << level[ level_index ]
    end
    ary
  end.join('|') + '|'
end


def parse_sox_stats( stats_str )
  begin
    [ 'DC offset', 'Min level', 'Max level', 'Pk lev dB', 'RMS lev dB', 'RMS Pk dB', 'RMS Tr dB', 'Crest factor', 'Flat factor', 'Pk count', 'Bit-depth', 'Num samples', 'Length s', 'Scale max', 'Window s' ].inject( {} ) do |hash, item|
      values = stats_str.match( /^#{ item }.+$/ )[ 0 ].split( /\s+/ ).reject { |e| item =~ /#{ e }/ }
      key = item.downcase.gsub( /\W/, '_' ).to_sym
      hash[ key ] = { :overall => values[ 0 ], :channels => values[ 1 .. -1 ] }
      hash
    end
  rescue Exception => e
    @logger.info e.message
    return {}
  end
end


def audio_characteristics( pipe, asset_file, channel_count, entry_point, duration, key = nil )
  unwrap_call = "asdcp-unwrap -f #{ entry_point } -d #{ duration } #{ key ? '-k ' + key : '' } #{ Shellwords.escape asset_file } #{ pipe.path } 2>/dev/null"
  pid = Process.spawn( unwrap_call )
  Process.detach pid
  system( 'sleep 0.1' )
  sox_call = "sox -t wavpcm #{ pipe.path } -n stats"
  out, err, status = Open3.capture3( sox_call )
  parse_sox_stats( err )
end


# lib/magic_strings.rb
module MStr
  Smpte_am    = 'http://www.smpte-ra.org/schemas/429-9/2007/AM'
  Smpte_pkl   = 'http://www.smpte-ra.org/schemas/429-8/2007/PKL'
  Smpte_cpl   = 'http://www.smpte-ra.org/schemas/429-7/2006/CPL'
  Interop_am  = 'http://www.digicine.com/PROTO-ASDCP-AM-20040311#'
  Interop_pkl = 'http://www.digicine.com/PROTO-ASDCP-PKL-20040311#'
  Interop_cpl = 'http://www.digicine.com/PROTO-ASDCP-CPL-20040511#'
  Composition_metadata_href = [ 'http://isdcf.com/schemas/draft/2011/cpl-metadata', 'http://www.smpte-ra.org/schemas/429-16/2014/CPL-Metadata' ]

  Ns_Xmldsig  = 'http://www.w3.org/2000/09/xmldsig#'

  Schemas = {
    Smpte_am    => 'SMPTE-429-9-2007-AM.xsd',
    Smpte_pkl   => 'SMPTE-429-8-2006-PKL.xsd',
    Smpte_cpl   => 'SMPTE-429-7-2006-CPL.xsd',
    Interop_am  => 'PROTO-ASDCP-AM-20040311.xsd',
    Interop_pkl => 'PROTO-ASDCP-PKL-20040311.xsd',
    Interop_cpl => 'PROTO-ASDCP-CPL-20040511.xsd'
  }

  # asdcp-info answers include
  Stereoscopic_pictures = 'stereoscopic pictures'
  Pictures              = 'pictures'
  Mpeg2                 = 'MPEG2 video'
  Audio                 = 'audio'
  Atmos                 = 'Dolby ATMOS'
  Timed_text            = 'timed text'

  Tkr_attr = 'x-TKR'

  AssetTypeInterop      = 'Interop'
  AssetTypeSmpte        = 'SMPTE'
  AssetTypeUnknown      = 'Unknown'
  AssetTypeMixed        = 'Mixed'
  AssetTypeUndetermined = 'Undetermined'

  TTF = 'Font TrueType'
  OTF = 'Font CFF-based'

  Cpl_content_kind_default_scope = 'http://www.smpte-ra.org/schemas/429-7/2006/CPL#standard-content'
  Cpl_standard_content = [ 'feature', 'trailer', 'test', 'teaser', 'rating', 'advertisement', 'short', 'transitional', 'psa', 'policy' ]
  Cpl_standard_content_moniker_map = { :ftr => :feature, :tlr => :trailer, :tst => :test, :tsr => :teaser, :rtg => :rating, :pol => :policy, :adv => :advertisement, :shr => :short, :xsn => :transitional, :psa => :psa }

  #
  # RFC-4122:
  # The hexadecimal values "a" through "f" are output as
  # lower case characters and are case insensitive on input.
  #
  Uuid_rfc4122_re = /^[0-9a-f]{8}-[0-9a-f]{4}-([1-5])[0-9a-f]{3}-[8-9a-b][0-9a-f]{3}-[0-9a-f]{12}$/i

  Uuid_re = /^[0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12}$/i
  Uuid_particle_re = /[0-9a-f]{8}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{4}-[0-9a-f]{12}/i # used for filename component

end # module MStr


# lib/shell_tools.rb
module Shell
  class << self
    def uuid_new
      `kmuuidgen -n`
    end
    def asdcp_mxf_info( filename )
      out, err, status = Open3.capture3( "asdcp-info -v -i -d -r #{ Shellwords.shellescape filename }" )
      out = out.chomp
      return out, err, status
    end
    def asdcp_mxf_interop_stereoscopic_info( filename )
      out, err, status = Open3.capture3( "asdcp-info -3 -v -i -d -r #{ Shellwords.shellescape filename }" )
      out = out.chomp
      return out, err, status
    end
  end
end


class Numeric
  TERA = 1099511627776.0
  GIGA = 1073741824.0
  MEGA = 1048576.0
  KILO = 1024.0
  def to_k
    case
    when self == 1 then '1 Byte'
    when self < KILO then "%d Bytes" % self
    when self < MEGA then "%.1f KB" % ( self / KILO )
    when self < GIGA then "%.1f MB" % ( self / MEGA )
    when self < TERA then "%.1f GB" % ( self / GIGA )
    else "%.1f TB" % ( self / TERA )
    end
  end
end


# Glyph availability
module TTFunk
  class File
    def provides_glyphs_for?( unicode_string )
      unicode_string.unpack("U*").all? { |c| cmap.unicode.first[c] > 0 }
    end
  end
end


# Signature counters
@signed_cpls_count = 0
@signed_cpls_verified_count = 0
@signed_pkls_count = 0
@signed_pkls_verified_count = 0

# Plaintext/Encrypted compositions counter
@encrypted_compositions = 0


# lib/tools.rb
# date helpers
require 'date'
def time_to_datetime( time ) # OpenSSL's ruby bindings return Time objects for certificate validity info
  DateTime.parse( time.to_s )
end

def datetime_friendly( dt ) # return something in the form of "Tuesday Nov 30 2010 (18:56)"
  "#{ DateTime::DAYNAMES[ dt.wday ] } #{ DateTime::ABBR_MONTHNAMES[ dt.month ] } #{ dt.day.to_s } #{ dt.year.to_s } #{ '%02d' % dt.hour.to_s }:#{ '%02d' % dt.min.to_s }"
end
RunDatetime = time_to_datetime AppStartSeconds
RunDatetime_friendly = datetime_friendly RunDatetime

def yyyymmdd( datetime ) # used in KDM filenames. See http://www.kdmnamingconvention.com/
  datetime.to_s.split( 'T' ).first.gsub( /-/,'' )
end

def hours_minutes_seconds_verbose( seconds )
  t = seconds
  hrs = ( ( t / 3600 ) ).to_i
  min = ( ( t / 60 ) % 60 ).to_i
  sec = t % 60
  return [
    hrs > 0 ? hrs.to_s + " hour#{ 's' * ( hrs > 1 ? 1 : 0 ) }" : nil ,
    min > 0 ? min.to_s + " minute#{ 's' * ( min > 1 ? 1 : 0 ) }" : nil ,
    sec == 1 ? sec.to_i.to_s + ' second' : sec != 0 ? sec.to_s + ' seconds' : nil ,
    t > 60 ? "(#{ t } seconds)" : nil
  ].compact.join( ' ' )
end

def hms_from_seconds( seconds )
  hours = ( seconds / 3600.0 ).to_i
  minutes = ( ( seconds / 60.0 ) % 60 ).to_i
  secs = seconds % 60
  return [ hours, minutes, secs ].join( ':' )
end

def seconds_from_hms( timestring ) # hh:mm:ss.fraction
  a = timestring.split( ':' )
  hours = a[ 0 ].to_i
  minutes = a[ 1 ].to_i
  secs = a[ 2 ].to_f
  return ( hours * 3600 + minutes * 60 + secs )
end

def time_string( t )
  return "--:--:--" if t.nil?
  t = t.to_i; s = t % 60; m  = ( t / 60 ) % 60; h = t / 3600
  "%02d:%02d:%02d" % [ h, m, s ]
end

# Adapted from actionpack-3.2.11/lib/action_view/helpers/date_helper.rb
def distance_of_time_in_words(from_time, to_time = 0, include_seconds = false, options = {})
  from_time = from_time.to_time if from_time.respond_to?(:to_time)
  to_time = to_time.to_time if to_time.respond_to?(:to_time)
  distance_in_minutes = (((to_time - from_time).abs)/60).round
  distance_in_seconds = ((to_time - from_time).abs).round

  case distance_in_minutes
  when 0..1
    return distance_in_minutes == 0 ?
      "less than 1 minute" :
      "#{ amount 'minute', distance_in_minutes }" unless include_seconds

    case distance_in_seconds
    when 0..59   then "less than 1 minute"
    else             "1 minute"
    end

  when 2..44           then "#{ amount 'minute', distance_in_minutes }"
  when 45..89          then "about 1 hour"
  when 90..1439        then "about #{ amount 'hour', (distance_in_minutes.to_f / 60.0).round }"
  when 1440..2519      then "1 day"
  when 2520..43199     then "#{ amount 'day', (distance_in_minutes.to_f / 1440.0).round }"
  when 43200..86399    then "about 1 month"
  when 86400..525599   then "#{ amount 'month', (distance_in_minutes.to_f / 43200.0).round }"
  else
    fyear = from_time.year
    fyear += 1 if from_time.month >= 3
    tyear = to_time.year
    tyear -= 1 if to_time.month < 3
    leap_years = (fyear > tyear) ? 0 : (fyear..tyear).count{|x| Date.leap?(x)}
    minute_offset_for_leap_year = leap_years * 1440
    minutes_with_offset         = distance_in_minutes - minute_offset_for_leap_year
    remainder                   = (minutes_with_offset % 525600)
    distance_in_years           = (minutes_with_offset / 525600)
    if remainder < 131400
      "about #{ amount 'year', distance_in_years }"
    elsif remainder < 394200
      "over #{ amount 'year', distance_in_years }"
    else
      "almost #{ amount 'year', distance_in_years + 1 }"
    end
  end
end

# misc helpers
#
class String
  def black;          "\e[30m#{self}\e[0m" end
  def red;            "\e[31m#{self}\e[0m" end
  def green;          "\e[32m#{self}\e[0m" end
  def brown;          "\e[33m#{self}\e[0m" end
  def blue;           "\e[34m#{self}\e[0m" end
  def magenta;        "\e[35m#{self}\e[0m" end
  def cyan;           "\e[36m#{self}\e[0m" end
  def gray;           "\e[37m#{self}\e[0m" end

  def bg_black;       "\e[40m#{self}\e[0m" end
  def bg_red;         "\e[41m#{self}\e[0m" end
  def bg_green;       "\e[42m#{self}\e[0m" end
  def bg_brown;       "\e[43m#{self}\e[0m" end
  def bg_blue;        "\e[44m#{self}\e[0m" end
  def bg_magenta;     "\e[45m#{self}\e[0m" end
  def bg_cyan;        "\e[46m#{self}\e[0m" end
  def bg_gray;        "\e[47m#{self}\e[0m" end

  def bold;           "\e[1m#{self}\e[22m" end
  def italic;         "\e[3m#{self}\e[23m" end
  def underline;      "\e[4m#{self}\e[24m" end
  def blink;          "\e[5m#{self}\e[25m" end # temptingudontknowhow
  def invert;  "\e[7m#{self}\e[27m" end
end

# turn items like '100KB' or '1.5 GB' to bytes
def bytes_from_nice_bytes( nice_bytes )
  parts = nice_bytes.downcase.split( /(kb|mb|gb)/ )
  n = Float( parts.first )
  if parts[ 1 ]
    case parts[ 1 ]
    when 'kb'
      n * Numeric::KILO.to_i
    when 'mb'
      n * Numeric::MEGA.to_i
    when 'gb'
      n * Numeric::GIGA.to_i
    end
  else
    n
  end
end

# plural helper english
def amount( item, count )
  if count.is_a? Array or count.is_a? Hash
    "#{ count.size } #{ item }#{ pl count }"
  elsif count.integer?
    "#{ count } #{ item }#{ pl count }"
  end
end
def plural( item, count )
  "#{ item }#{ pl count }"
end
def pl( count )
  if count.is_a? Array or count.is_a? Hash
    count.size != 1 ? 's' : ''
  elsif count.integer?
    count != 1 ? 's' : ''
  end
end

# Thanks to Rein Henrichs
def truncate( text, num_words = 6, truncate_string = " [...]" )
  if text.nil? then return end
  arr = text.split( ' ' )
  arr.length > num_words ? arr[ 0...num_words ].join( ' ' ) + truncate_string : text
end

# package path helper
def package( relative_path )
  # File.join( @package_dir, relative_path )
  relative_path
end

def print_inspection_messages( inspection )
  inspection[ :errors ].map { |e| @logger.errors [ 'Error', e ].join( ': ' ) }
  inspection[ :hints ].map { |e| @logger.hints [ 'Hint', e ].join( ': ' ) }
  inspection[ :info ].map { |e| @logger.info [ 'Info', e ].join( ': ' ) }
end


#
# lib/timecode-ticks_tc.rb (Julik's timecode -- https://github.com/guerilla-di/timecode + parse_with_ticks)
# Timecode is a convenience object for calculating SMPTE timecode natively. 
# The promise is that you only have to store two values to know the timecode - the amount
# of frames and the framerate. An additional perk might be to save the dropframeness,
# but we avoid that at this point.
#
# You can calculate in timecode objects as well as with conventional integers and floats.
# Timecode is immutable and can be used as a value object. Timecode objects are sortable.
#
class Timecode
  VERSION = '1.0.0'

  include Comparable

  DEFAULT_FPS = 25.0

  #:stopdoc:
  NTSC_FPS = (30.0 * 1000 / 1001).freeze
  FILMSYNC_FPS = (24.0 * 1000 / 1001).freeze
  ALLOWED_FPS_DELTA = (0.001).freeze

  COMPLETE_TC_RE = /^(\d{2}):(\d{2}):(\d{2}):(\d{2})$/
  COMPLETE_TC_RE_24 = /^(\d{2}):(\d{2}):(\d{2})\+(\d{2})$/
  DF_TC_RE = /^(\d{1,2}):(\d{1,2}):(\d{1,2});(\d{2})$/
  FRACTIONAL_TC_RE = /^(\d{2}):(\d{2}):(\d{2})\.(\d{1,8})$/
  TICKS_TC_RE = /^(\d{2}):(\d{2}):(\d{2}):(\d{3})$/

  WITH_FRACTIONS_OF_SECOND = "%02d:%02d:%02d.%02d"
  WITH_FRAMES = "%02d:%02d:%02d:%02d"
  WITH_FRAMES_24 = "%02d:%02d:%02d+%02d"

  #:startdoc:

  # All Timecode lib errors inherit from this
  class Error < RuntimeError; end

  # Gets raised if timecode is out of range (like 100 hours long)
  class RangeError < Error; end

  # Gets raised when a timecode cannot be parsed
  class CannotParse < Error; end

  # Gets raised when you try to compute two timecodes with different framerates together
  class WrongFramerate < ArgumentError; end

  # Initialize a new Timecode object with a certain amount of frames and a framerate
  # will be interpreted as the total number of frames
  def initialize(total = 0, fps = DEFAULT_FPS)
    raise WrongFramerate, "FPS cannot be zero" if fps.zero?

    # If total is a string, use parse
    raise RangeError, "Timecode cannot be negative" if total.to_i < 0
    # Always cast framerate to float, and num of rames to integer
    @total, @fps = total.to_i, fps.to_f
    @value = validate!
    freeze
  end

  def inspect # :nodoc:
    "#<Timecode:%s (%dF@%.2f)>" % [to_s, total, fps]
  end

  class << self

    # Use initialize for integers and parsing for strings
    def new(from, fps = DEFAULT_FPS)
      from.is_a?(String) ? parse(from, fps) : super(from, fps)
    end

    # Parse timecode and return zero if none matched
    def soft_parse(input, with_fps = DEFAULT_FPS)
      parse(input) rescue new(0, with_fps)
    end

    # Parse timecode entered by the user. Will raise if the string cannot be parsed.
    # The following formats are supported:
    # * 10h 20m 10s 1f (or any combination thereof) - will be disassembled to hours, frames, seconds and so on automatically
    # * 123 - will be parsed as 00:00:01:23
    # * 00:00:00:00 - will be parsed as zero TC
    def parse(input, with_fps = DEFAULT_FPS)
      # Drop frame goodbye
      if (input =~ DF_TC_RE)
        raise Error, "We do not support drop-frame TC"
      # 00:00:00:00
      elsif (input =~ COMPLETE_TC_RE)
        atoms_and_fps = input.scan(COMPLETE_TC_RE).to_a.flatten.map{|e| e.to_i} + [with_fps]
        return at(*atoms_and_fps)
      # 00:00:00+00
      elsif (input =~ COMPLETE_TC_RE_24)
        atoms_and_fps = input.scan(COMPLETE_TC_RE_24).to_a.flatten.map{|e| e.to_i} + [24]
        return at(*atoms_and_fps)
      # 00:00:00.0
      elsif input =~ FRACTIONAL_TC_RE
        parse_with_fractional_seconds(input, with_fps)
      # 00:00:00:000
      elsif input =~ TICKS_TC_RE
        parse_with_ticks(input, with_fps)
      # 10h 20m 10s 1f 00:00:00:01 - space separated is a sum of parts
      elsif input =~ /\s/
        parts = input.gsub(/\s/, ' ').split.reject{|e| e.strip.empty? }
        raise CannotParse, "No atoms" if parts.empty?
        parts.map{|part|  parse(part, with_fps) }.inject{|sum, p| sum + p.total }
      # 10s
      elsif input =~ /^(\d+)s$/
        return new(input.to_i * with_fps, with_fps)
      # 10h
      elsif input =~ /^(\d+)h$/i
        return new(input.to_i * 60 * 60 * with_fps, with_fps)
      # 20m
      elsif input =~ /^(\d+)m$/i
        return new(input.to_i * 60 * with_fps, with_fps)
      # 60f - 60 frames, or 2 seconds and 10 frames
      elsif input =~ /^(\d+)f$/i
        return new(input.to_i, with_fps)
      # Only a bunch of digits, treat 12345 as 00:01:23:45
      elsif (input =~ /^(\d+)$/)
        atoms_len = 2 * 4
        # left-pad input AND truncate if needed
        padded = input[0..atoms_len].rjust(8, "0")
        atoms = padded.scan(/(\d{2})/).flatten.map{|e| e.to_i } + [with_fps]
        return at(*atoms)
      else
        raise CannotParse, "Cannot parse #{input} into timecode, unknown format"
      end
    end

    # Initialize a Timecode object at this specfic timecode
    def at(hrs, mins, secs, frames, with_fps = DEFAULT_FPS)
      validate_atoms!(hrs, mins, secs, frames, with_fps)
      total = (hrs*(60*60*with_fps) +  mins*(60*with_fps) + secs*with_fps + frames).round
      new(total, with_fps)
    end

    # Validate the passed atoms for the concrete framerate
    def validate_atoms!(hrs, mins, secs, frames, with_fps)
      case true
        when hrs > 999
          raise RangeError, "There can be no more than 999 hours, got #{hrs}"
        when mins > 59
          raise RangeError, "There can be no more than 59 minutes, got #{mins}"
        when secs > 59
          raise RangeError, "There can be no more than 59 seconds, got #{secs}"
        when frames > (with_fps - 1)
          raise RangeError, "There can be no more than #{with_fps - 1} frames @#{with_fps}, got #{frames}"
      end
    end

    # Parse a timecode with fractional seconds instead of frames. This is how ffmpeg reports
    # a timecode
    def parse_with_fractional_seconds(tc_with_fractions_of_second, fps = DEFAULT_FPS)
      fraction_expr = /\.(\d+)$/
      fraction_part = ('.' + tc_with_fractions_of_second.scan(fraction_expr)[0][0]).to_f

      seconds_per_frame = 1.0 / fps.to_f
      frame_idx = (fraction_part / seconds_per_frame).floor

      tc_with_frameno = tc_with_fractions_of_second.gsub(fraction_expr, ":%02d" % frame_idx)

      parse(tc_with_frameno, fps)
    end

    # Parse a timecode with ticks of a second instead of frames. A 'tick' is defined as 
    # 4 msec and has a range of 0 to 249. This format can show up in subtitle files for digital cinema
    def parse_with_ticks(tc_with_ticks, fps = DEFAULT_FPS)
      ticks_expr = /(\d{3})$/ 
      ticks_part = (tc_with_ticks.scan(ticks_expr)[0][0]).to_i

      seconds_per_frame = 1.0 / fps
      frame_idx = ((ticks_part * 0.004) / seconds_per_frame ).floor

      tc_with_frameno = tc_with_ticks.gsub(ticks_expr, "%02d" % frame_idx)

      parse(tc_with_frameno, fps)
    end

    # create a timecode from the number of seconds. This is how current time is supplied by
    # QuickTime and other systems which have non-frame-based timescales
    def from_seconds(seconds_float, the_fps = DEFAULT_FPS)
      total_frames = (seconds_float.to_f * the_fps.to_f).to_i
      new(total_frames, the_fps)
    end

    # Some systems (like SGIs) and DPX format store timecode as unsigned integer, bit-packed. This method
    # unpacks such an integer into a timecode.
    def from_uint(uint, fps = DEFAULT_FPS)
      tc_elements = (0..7).to_a.reverse.map do | multiplier | 
        ((uint >> (multiplier * 4)) & 0x0F)
      end.join.scan(/(\d{2})/).flatten.map{|e| e.to_i}

      tc_elements << fps
      at(*tc_elements)
    end
  end

  def coerce(to)
    me = case to
      when String
        to_s
      when Integer
        to_i
      when Float
        to_f
      else
        self
    end
    [me, to]
  end

  # is the timecode at 00:00:00:00
  def zero?
    @total.zero?
  end

  # get total frame count
  def total
    to_f
  end

  # get FPS
  def fps
    @fps
  end

  # get the number of frames
  def frames
    value_parts[3]
  end

  # get the number of seconds
  def seconds
    value_parts[2]
  end

  # get the number of minutes
  def minutes
    value_parts[1]
  end

  # get the number of hours
  def hours
    value_parts[0]
  end

  # get frame interval in fractions of a second
  def frame_interval
    1.0/@fps
  end

  # get the timecode as bit-packed unsigned 32 bit int (suitable for DPX and SGI)
  def to_uint
    elements = (("%02d" * 4) % [hours,minutes,seconds,frames]).split(//).map{|e| e.to_i }
    uint = 0
    elements.reverse.each_with_index do | p, i |
      uint |= p << 4 * i 
    end
    uint
  end

  # get the timecode as a floating-point number of seconds (used in Quicktime)
  def to_seconds
    (@total / @fps)
  end

  # Convert to different framerate based on the total frames. Therefore,
  # 1 second of PAL video will convert to 25 frames of NTSC (this 
  # is suitable for PAL to film TC conversions and back).
  def convert(new_fps)
    self.class.new(@total, new_fps)
  end

  # get formatted SMPTE timecode
  def to_s
    if (framerate_in_delta(fps, 24))
      WITH_FRAMES_24 % value_parts
    else
      WITH_FRAMES % value_parts
    end
  end

  # get total frames as float
  def to_f
    @total
  end

  # get total frames as integer
  def to_i
    @total
  end

  # add number of frames (or another timecode) to this one
  def +(arg)
    if (arg.is_a?(Timecode) && framerate_in_delta(arg.fps, @fps))
      self.class.new(@total+arg.total, @fps)
    elsif (arg.is_a?(Timecode))
      raise WrongFramerate, "You are calculating timecodes with different framerates"
    else
      self.class.new(@total + arg, @fps)
    end
  end

  # Tells whether the passes timecode is immediately to the left or to the right of that one
  # with a 1 frame difference
  def adjacent_to?(another)
    (self.succ == another) || (another.succ == self)
  end

  # Subtract a number of frames
  def -(arg)
    if (arg.is_a?(Timecode) &&  framerate_in_delta(arg.fps, @fps))
      self.class.new(@total-arg.total, @fps)
    elsif (arg.is_a?(Timecode))
      raise WrongFramerate, "You are calculating timecodes with different framerates"
    else
      self.class.new(@total-arg, @fps)
    end
  end

  # Multiply the timecode by a number
  def *(arg)
    raise RangeError, "Timecode multiplier cannot be negative" if (arg < 0)
    self.class.new(@total*arg.to_i, @fps)
  end

  # Get the next frame
  def succ
    self.class.new(@total + 1, @fps)
  end

  # Get the number of times a passed timecode fits into this time span (if performed with Timecode) or 
  # a Timecode that multiplied by arg will give this one
  def /(arg)
    arg.is_a?(Timecode) ?  (@total / arg.total) : self.class.new(@total / arg, @fps)
  end

  # Timecodes can be compared to each other
  def <=>(other_tc)
    if framerate_in_delta(fps, other_tc.fps)
      self.total <=> other_tc.total
    else 
      raise WrongFramerate, "Cannot compare timecodes with different framerates"
    end
  end

  # FFmpeg expects a fraction of a second as the last element instead of number of frames. Use this
  # method to get the timecode that adheres to that expectation. The return of this method can be fed
  # to ffmpeg directly.
  #  Timecode.parse("00:00:10:24", 25).with_frames_as_fraction #=> "00:00:10.96"
  def with_frames_as_fraction
    vp = value_parts.dup
    vp[-1] = (100.0 / @fps) * vp[-1]
    WITH_FRACTIONS_OF_SECOND % vp
  end
  alias_method :with_fractional_seconds, :with_frames_as_fraction

  # Validate that framerates are within a small delta deviation considerable for floats
  def framerate_in_delta(one, two)
    (one.to_f - two.to_f).abs <= ALLOWED_FPS_DELTA
  end

  private

  # Prepare and format the values for TC output
  def validate!
    frames = @total
    secs = (@total.to_f/@fps).floor
    frames-=(secs*@fps)
    mins = (secs/60).floor
    secs -= (mins*60)
    hrs = (mins/60).floor
    mins-= (hrs*60)

    self.class.validate_atoms!(hrs, mins, secs, frames, @fps)

    [hrs, mins, secs, frames]
  end

  def value_parts
    @value ||= validate!
  end
end # Timecode


# TC helper: parse both hh:mm:ss:ttt and hh:mm:ss.sss TC formats used in DCSubtitle
def parse_dcsubtitle_tc_string( tc_string, fps )
  case tc_string
  when /\d\d:\d\d:\d\d:\d\d\d/ # hh:mm:ss:ttt
    Timecode.parse_with_ticks( tc_string, fps )
  when /\d\d:\d\d:\d\d\.\d\d\d/ # hh:mm:ss.sss
    Timecode.parse( tc_string, fps )
  else
    nil
  end
end


class DC_Signer_Crypto_Compliance
  attr_reader :context, :errors, :crypto_context_valid, :type
  def initialize( certs )
    crypto_context( certs )
  end

  def crypto_context( certs )
    @errors = Hash.new
    @context, @errors[ :pre_context ] = find_crypto_context( certs )
    if @errors[ :pre_context ].empty?
      @errors[ :context ], @types_seen = check_compliance
      if @errors[ :pre_context ].empty? and @errors[ :context ].values.flatten.empty? and @chain_verified == true
        if @types_seen.uniq.size == 1
          @type = @types_seen.first
          @crypto_context_valid = true
        else
          @type = 'Mixed'
          @crypto_context_valid = false
        end
      else
        @crypto_context_valid = false
      end
    else
      @crypto_context_valid = false
    end
  end # crypto_context

  def valid?
    @crypto_context_valid
  end

  def messages
    msgs = Array.new
    @context.each_with_index do |cert, index|
      msgs << "Subject: #{ cert.subject.to_s }"
      msgs << "Issuer:  #{ cert.issuer.to_s }"
      unless @errors[ :context ].nil?
        if @errors[ :context ][ cert.subject.to_s ].empty?
          msgs << 'OK ✅'
        else
          msgs << "Not a #{ @types_seen[ index ] } compliant certificate: ❌"
          @errors[ :context][ cert.subject.to_s ].each do |error|
            msgs << "\t" + error
          end
        end
      end
    end
    msgs << "Chain signatures #{ @chain_verified == true ? 'verified' : 'verification failed ❌' }"
    if total_errors == 0
      msgs << "Compliant certificate chain found: #{ @type } (#{ context.to_a.sizmsgs } certificates, 0 errors)"
    else
      msgs << "Not a compliant certificate chain ❌: #{ context.to_a.size } certificate#{ context.to_a.size != 1 ? 's' : '' } with #{ total_errors } error#{ total_errors != 1 ? 's' : '' }"
    end
    return msgs
  end

  def find_crypto_context( pems )
    context = Array.new
    pre_context_errors = Array.new

    pems.each do |pem|
      begin
        cert_obj = OpenSSL::X509::Certificate.new( pem )
        context << cert_obj
      rescue
        # catch all exceptions (scan or CertificateError) and move on
      end
    end

    # Find root ca and collect issuers
    # ruby version of CTP's dsig_cert.py
    root = nil
    issuer_map = Hash.new

    context.each do |cert|
      if cert.issuer.to_s == cert.subject.to_s
        if root
          pre_context_errors << 'Multiple self-signed (root) certificates found ❌'
          return [], pre_context_errors
        else
          root = cert
        end
      else
        issuer_map[ cert.issuer.to_s ] = cert
      end
    end
    if root == nil
      pre_context_errors << 'Self-signed root certificate not found ❌'
      return [], pre_context_errors
    end

    # sort
    tmp_list = Array.new
    tmp_list << root
    begin
      key = tmp_list.last.subject.to_s
      child = issuer_map[ key ]
      while child
        tmp_list << child
        key = tmp_list.last.subject.to_s
        child = issuer_map[ key ]
      end
    rescue
      nil
    end # ruby version of CTP's dsig_cert.py

    if tmp_list.size == 1
      pre_context_errors << 'No issued certificates found ❌'
      return context, pre_context_errors
    end

    if context.size != tmp_list.size
      pre_context_errors << 'Certificates do not form a complete chain ❌'
      return context, pre_context_errors
    end
    # from here on 1st is leaf, 2nd .. n are intermediate ca's, last is self-signed root ca
    context = tmp_list.reverse
    return context, pre_context_errors
  end # find_crypto_context

  def check_compliance
    context_errors = Hash.new
    types_seen = Array.new
    @context.each_with_index do |member, index|
      cert = member
      type = nil
      errors = Array.new
      errors << 'Not a X509 certificate ❌' unless cert.is_a?( OpenSSL::X509::Certificate )
      # ctp sections:

      # 2.1.1 X.509 version 3
      errors << 'Not X509 version 3 ❌' unless cert.version == 2 # sic. versions 1 2 3 -> 0 1 2

      # 2.1.1 Issuer and subject present
      errors << 'Issuer missing ❌' unless cert.issuer.is_a?( OpenSSL::X509::Name )
      errors << 'Subject missing ❌' unless cert.subject.is_a?( OpenSSL::X509::Name )

      # * 2.1.2 Signature algorithm
      case cert.signature_algorithm
      when 'sha256WithRSAEncryption'
        type = :smpte
      when 'sha1WithRSAEncryption'
        type = :interop
      else
        errors << 'Signature algorithm not sha256WithRSAEncryption or sha1WithRSAEncryption ❌'
      end

      # 2.1.3
      # Implicitly checked above

      # * 2.1.4 Serial number field non-negative integer less or equal to 64 or 160 bits respectively
      case type
      when :smpte
        errors << 'Serial number not in valid range ❌' unless 0 <= cert.serial.to_i and cert.serial.to_i <= 2 ** 64
      when :interop
        errors << 'Serial number not in valid range ❌' unless 0 <= cert.serial.to_i and cert.serial.to_i <= 2 ** 160
      else
        errors << 'Serial number not checked (Certificate type has not been established) ❌'
      end

      # 2.1.5 SubjectPublicKeyInfo field modulus 2048 bit and e == 65537
      errors << 'Modulus not 2048 bits long ❌' unless cert.public_key.n.to_i.size == 256 # 'n' is modulus (as OpenSSL::BN)
      errors << 'Public exponent not 65537 ❌' unless cert.public_key.e == 65537 # 'e' is public exponent (OpenSSL::BN)

      # 2.1.6 Deleted (in CTP 1.1) section

      # 2.1.7 Validity present (not before, not after)
      #
      # Note on Ruby version 1.8.7:
      #
      # UTC time > jan 19th 2038 is broken in ruby 1.8.7 on 32 bit systems (See https://bugs.ruby-lang.org/issues/5885)
      # See {"o"=>"DC256.Cinea.Com"} {"ou"=>"Root-CA.DC256.Cinea.Com"} {"cn"=>".Cinea.Root-CA.0"} {"dnq"=>"NFkBZDCGa7KpLK0PhZNCt40dDi8="} {"not_before"=>2006-05-12 16:08:58 UTC} {"not_after"=>2041-05-01 00:00:00 UTC} for a valid X509 cert exceeding 32 bit time_t.
      # See COFD-3D_FTR-8_C_EN-XX_US_51_2K_20110308_DLB_i3D for a package with NFkBZDCGa7KpLK0PhZNCt40dDi8=.
      # See DC_Signer_Crypto_Compliance Section 2.1.17 for another spot where this matters.
      #
      begin
        errors << 'Not before field missing ❌' if cert.not_before.nil?
        errors << 'Not after field missing ❌' if cert.not_after.nil?
        errors << 'Not before field is not UTC ❌' unless cert.not_before.utc?
        errors << 'Not after field is not UTC ❌' unless cert.not_after.utc?
      rescue Exception => e
        errors << "Internal error: Skip DC_Signer_Crypto_Compliance Section 2.1.7 Validity: RUBY_VERSION #{ RUBY_VERSION } on 32 bit systems broken for UTC times > Jan 19th 2038. Inspect certificate manually ❌" if e.class == ArgumentError
      end

      # Check X.509 extensions
      required_oids = %w( basicConstraints keyUsage authorityKeyIdentifier )
      additional_oids = Array.new

      cert.extensions.each do |x|
        if required_oids.include?( x.oid )
          required_oids.delete( x.oid )
          values = extension_values( x.value )

          case x.oid

          # 2.1.8 AuthorityKeyIdentifier field present
          when 'authorityKeyIdentifier'
            nil # 2.1.8 checks for presence only. Omission in CTP?

          # 2.1.9 KeyUsage field
          when 'keyUsage'
            if index == 0 # leaf cert
              errors << 'digitalSignature missing from keyUsage ❌' unless values.include?( 'Digital Signature' )
              errors << 'keyEncipherment missing from keyUsage ❌' unless values.include?( 'Key Encipherment' )
            else # ca's
              errors << 'keyCertSign missing from keyUsage ❌' unless values.include?( 'Certificate Sign' )
            end

          # * 2.1.10 basicConstraints field
          when 'basicConstraints'
            if index == 0 # leaf cert
              errors << "CA true in potential #{ type } leaf certificate ❌" unless values.include?( 'CA:FALSE' )
              case type
              when :smpte
                if values.find { |v| v.match( /pathlen:[^0]/ ) }
                  errors << "Pathlen present and non-zero in potential #{ type } leaf certificate ❌"
                end
              when :interop
                if values.find { |v| v.match( /pathlen:[^0]/ ) }
                  errors << "Pathlen present and non-zero in potential #{ type } leaf certificate ❌"
                end
              end
            else # ca's
              errors << 'basicConstraints not marked critical ❌' unless x.critical?
              errors << 'CA false for authority certificate ❌' unless values.include?( 'CA:TRUE' )
              if ! values.find { |v| v.match( /pathlen:\d+/ ) }
                # FIXME If the value in pathlen is negative the regexp above will not match
                # and thus trigger the error but the message will be misleading
                errors << 'Pathlen missing for authority certificate ❌'
              end
            end
          end # case oid
        else
          additional_oids << x # see 2.1.15 checks
        end # required oid
      end # extensions
      errors << "Extensions #{ required_oids.join( ', ' ) } missing ❌" unless required_oids.empty?

      # 2.1.11 Public key thumbprint dnQualifier
      #
      if RUBY_VERSION < '1.9.3'
        # works for rubies < 1.9.3:
        asn1 = Base64.decode64( cert.public_key.to_pem.split( "\n" )[ 1 .. -2 ].join )
        dnq_calc = Base64.encode64( OpenSSL::Digest.new( 'sha1', asn1 ).digest ).chomp
      else
        # rubies >= 1.9.3 changed the default encoding of public key so do this instead:
        pkey_der = OpenSSL::ASN1::Sequence( [ OpenSSL::ASN1::Integer( cert.public_key.n ), OpenSSL::ASN1::Integer( cert.public_key.e ) ] ).to_der
        dnq_calc = Base64.encode64( OpenSSL::Digest.new( 'sha1', pkey_der ).digest ).chomp
      end
      #
      field_dnq = find_field( 'dnQualifier', cert.subject )
      if field_dnq.empty?
        errors << 'dnQualifier field missing in subject name ❌'
      elsif field_dnq.size > 1
        errors << 'More than 1 dnQualifier field present ❌'
      else
        dnq_cert = field_dnq.first[ 1 ]
        if dnq_cert.empty?
          errors << 'dnQualifier missing in subject name ❌'
        end
        if dnq_calc != dnq_cert
          errors << 'dnQualifier mismatch ❌'
        end
      end

      # 2.1.12 OrganizationName field present in issuer and subject and identical
      field_o_issuer = find_field( 'O', cert.issuer )
      field_o_subject = find_field( 'O', cert.subject )
      if field_o_issuer.empty?
        errors << 'Organization name field missing in issuer name ❌'
      elsif field_o_issuer.size > 1
        errors << 'More than 1 Organization name field present in issuer name ❌'
      else
        o_issuer = field_o_issuer.first[ 1 ]
      end
      if field_o_subject.empty?
        errors << 'Organization name missing in subject name ❌'
      elsif field_o_subject.size > 1
        errors << 'More than 1 Organization name field present in subject name ❌'
      else
        o_subject = field_o_subject.first[ 1 ]
      end
      unless o_issuer.nil? and o_subject.nil?
        if o_issuer != o_subject
          errors << 'Organization name issuer/subject mismatch ❌'
        end
      end

      # 2.1.13 OrganizationUnitName field
      field_ou_issuer = find_field( 'OU', cert.issuer )
      field_ou_subject = find_field( 'OU', cert.subject )
      if field_ou_issuer.empty?
        errors << 'OrganizationUnit field missing in issuer name❌'
      elsif field_ou_issuer.size > 1
        errors << 'More than 1 OrganizationUnit fields present in issuer name ❌'
      else
        ou_issuer = field_ou_issuer.first[ 1 ]
      end
      if field_ou_subject.empty?
        errors << 'OrganizationUnit field missing in subject name ❌'
      elsif field_ou_subject.size > 1
        errors << 'More than 1 OrganizationUnit fields present in subject name ❌'
      else
        ou_subject = field_ou_subject.first[ 1 ]
      end
      if ou_issuer.nil?
        errors << 'OrganizationUnit name of issuer empty ❌'
      end
      if ou_subject.nil?
        errors << 'OrganizationUnit name of subject empty ❌'
      end

      # 2.1.14 Entity name and roles field
      field_cn_issuer = find_field( 'CN', cert.issuer )
      field_cn_subject = find_field( 'CN', cert.subject )
      if field_cn_issuer.empty?
        errors << 'CommonName field missing in issuer name ❌'
      elsif field_cn_issuer.size > 1
        errors << 'More than 1 CommonName field present in issuer name ❌'
      else
        cn_issuer = field_cn_issuer.first[ 1 ]
      end
      if field_cn_subject.empty?
        errors << 'CommonName field missing in subject name ❌'
      elsif field_cn_subject.size > 1
        errors << 'More than 1 CommonName field present in subject name ❌'
      else
        cn_subject = field_cn_subject.first[ 1 ]
        cn_subject_roles = cn_subject.split( /\..+/ )
        if cn_subject_roles.empty?
          roles = nil
        else
          roles = cn_subject_roles.first.split( ' ' )
        end
      end

      if index == 0 # leaf
        case type
        when :smpte
          if cn_subject_roles.empty?
            errors << 'Role title missing in CommonName field of leaf certificate subject name ❌'
          else
            errors << 'CS role missing in CommonName field of leaf certificate subject name  ❌' unless roles.include?( 'CS' )
            errors << 'Superfluous roles present in CommonName field of leaf certificate subject name  ❌' unless roles.size == 1 and roles[ 0 ] == 'CS'
          end
        when :interop
          # lax rules noop
        end
      else # ca's
        errors << 'Role title present in CommonName field of authority certificate ❌' unless roles.nil?
      end

      # 2.1.15 unrecognized x509v3 extensions not marked critical
      additional_oids.each do |x|
        errors << 'Additional, non-required X.509v3 extension is marked critical ❌' if x.critical?
      end

      context_errors[ cert.subject.to_s ] = errors
      types_seen << type
    end # @context.each

    # 2.1.16 signature verification. verify chain
    @chain_verified, context_errors = verify_cert_chain( @context, context_errors )

    # 2.1.17 Chain complete? Validity period of child cert contained within validity of parent? Root ca valid?
    # The chain completeness and root ca checks are implicit in crypto_context() which leaves validity containment checks:
    @context.each_with_index do |cert, index|
      break if index == @context.size - 1 # root ca
      begin
        if ! ( cert.not_before >= @context[ index + 1 ].not_before and cert.not_after <= @context[ index + 1 ].not_after )
          context_errors[ cert.subject.to_s ] << "Validity period not contained within parent certificate's validity period ❌"
        end
      rescue Exception => e
        context_errors[ cert.subject.to_s ] << "Internal error: Skip DC_Signer_Crypto_Compliance Section 2.1.17 Chain completeness: RUBY_VERSION #{ RUBY_VERSION } on 32 bit systems broken for UTC times > Jan 19th 2038. Inspect certificate manually ❌" if e.class == ArgumentError
      end
    end
    return context_errors, types_seen
  end # check_compliance

  # Verify a sorted certificate chain
  def verify_cert_chain( certs, context_errors )
    certs = certs.reverse
    verification = Array.new
    certs.each_with_index do |cert, index|
      if index == 0 then issuer = cert else issuer = certs[ index - 1 ] end
      begin
        check = cert.verify issuer.public_key
        context_errors[ cert.subject.to_s ] << 'Verification with issuer public key failed ❌' if check == false
        verification << check
      rescue Exception => e
        verification << e
      end
    end
    if verification.uniq.size == 1 and verification.first == true
      return true, context_errors
    else
      return false, context_errors
    end
  end

  def find_field( fieldname, x509_name )
    x509_name.to_a.find_all { |e| e.first.match '^' + fieldname + '$' }
  end

  def extension_values( string )
    string.split( ', ' )
  end

  def each
    @context.each {|f| yield( f ) }
  end

  def to_a
    @context.dup
  end

  def total_errors
    @errors[ :context ].values.flatten.size
  end
end # DC_Signer_Crypto_Compliance


class DC_Signature_Verification
  attr_reader :messages, :signer_node, :signature_node, :crypto, :reference_digests_check, :signature_value_check

  def initialize( doc )
    @messages = Array.new
    @signer_node = nil
    @signature_node = nil
    @crypto = nil
    @reference_digests_check = false
    @signature_value_check = false
    evaluation_complete = signature_verify( doc )
    report
  end

  def verified?
    @verified
  end

  def signer_name
    if @crypto
      @crypto.context.first.subject.to_s unless @crypto.context.empty?
    else
      ''
    end
  end
  def signer_issuer
    if @crypto
      @crypto.context.first.issuer.to_s unless @crypto.context.empty?
    else
      ''
    end
  end

  def report
    if @signature_node.size == 1
      case @reference_digests_check
      when true
        @messages << 'Document and SignedInfo match'
        case @signature_value_check
        when true
          @messages << 'Signature value and SignedInfo match'
        when false
          @messages << 'Signature value and SignedInfo do not match ❌'
        end

      when false
        @messages << 'Document and SignedInfo do not match ❌'
        case @signature_value_check
        when true
          @messages << 'Signature value and SignedInfo match'
        when false
          @messages << 'Signature value and SignedInfo do not match ❌'
        end
      end

      if @reference_digests_check and @signature_value_check
        @verified = true
        @messages << 'Signature check: OK ✅'
      else
        @verified = false
        @messages << 'Signature check: Verification failure ❌'
      end
    end
  end

  #
  # FIXME
  # Looking only at the first prefix returned from collect_all_namespaces_href_keys
  # for a given namespace will fall on its nose when there would be multiple prefixes
  # for the same namespace. E.g. I think in a Signature it would be entirely valid to
  # use different prefixes for different portions, all evaluating to the same namespace.
  #
  # Good enough for now but ktfim
  #
  def namespace_prefix( doc, ns )
    doc_ns = doc.collect_all_namespaces_href_keys
    if doc_ns.key?( ns )
      doc_ns[ ns ].first.nil? ? 'xmlns' : doc_ns[ ns ].first
    else
      'xmlns'
    end
  end

  def signature_namespace_and_prefix( doc )
    # If Signature's namespace is not in doc's namespace collection then it will be either
    #   * in Ns_Xmldsig declared as default namespace for Signature scope
    #   * or whacked beyond recognition
    doc_ns = doc.collect_namespaces
    if RUBY_VERSION < '1.9'
      # Hash#index will be deprecated in the ruby 1.9.x series. Is in here for 1.8.x
      if doc_ns.index( MStr::Ns_Xmldsig )
        prefix = doc_ns.index( MStr::Ns_Xmldsig ).split( 'xmlns:' ).last
      else
        prefix = 'xmlns'
      end
    else
      if doc_ns.key( MStr::Ns_Xmldsig )
        prefix = doc_ns.key( MStr::Ns_Xmldsig ).split( 'xmlns:' ).last
      else
        prefix = 'xmlns'
      end
    end
    sig_ns = { prefix => MStr::Ns_Xmldsig }
    return sig_ns, prefix
  end

  # Will return true/false for completing the evaluation
  # Actual verification results implied by @reference_digests_check and @signature_value_check
  def signature_verify( doc )
    # 1. Figure out signature namespace prefix
    sig_ns, prefix = signature_namespace_and_prefix( doc )

    # 2.a Signer present?
    @signer_node = doc.xpath( "//#{ namespace_prefix( doc, doc.root.namespace.href ) }:Signer" )
    if @signer_node.size != 1
      @messages << "#{ @signer_node.size == 0 ? 'No' : @signer_node.size } Signer node#{ @signer_node.size > 1 ? 's' : '' } found"
    end

    # 2.b Signature present?
    @signature_node = doc.xpath( "//#{ prefix }:Signature", sig_ns )
    if @signature_node.size != 1
      @messages << "#{ @signature_node.size == 0 ? 'No' : @signature_node.size } Signature node#{ @signature_node.size > 1 ? 's' : '' } found"
    end

    # 2.c Abort if none or more than 1 Signer or Signature node
    return false if ( @signer_node.size != 1 or @signature_node.size != 1 )

    # 3. Extract and check signer certs
    certs = extract_certs( doc, sig_ns, prefix )
    @crypto = DC_Signer_Crypto_Compliance.new( certs )

    if ! @crypto.valid?
      if ! @crypto.errors[ :pre_context ].empty?
        @crypto.errors[ :pre_context ].each do |e|
          @messages << e
        end
        return false
      else
        # Compliance issues in the extracted certs.
        # List those errors but then try to continue anyway,
        # thus allowing for inspection of compliance issues and signature in context.
        @crypto.messages.each do |e|
          @messages << e
        end
      end
    else # cc is valid
      @messages << "Certificate chain is complete and compliant (#{ @crypto.type })"
    end

    # 3.a Might check here whether the signer chain is known, trustworthy etc.
    #
    # See 3 for @crypto validity hop-over
    #

    # 4. Get signer's public key
    pub_k = @crypto.context.first.public_key

    # 5. Check references and signature value
    @reference_digests_check = check_references( doc, sig_ns, prefix )
    @signature_value_check = check_signature_value( doc, sig_ns, prefix, pub_k )

    return true
  end # signature_verify

  def check_signature_value( doc, sig_ns, prefix, pub_k )
    sig_algo = doc_signature_method_algorithm( doc, sig_ns, prefix )
    sig_digest_algo = sig_algo.split( 'rsa-' ).last
    signature_value_doc = extract_signature_value( doc, sig_ns, prefix )
    signature_value_doc_octets = signature_value_doc.size
    pub_k_octets = pub_k.n.to_i.size
    if signature_value_doc_octets != pub_k_octets
      @messages << "Invalid signature ❌: decoded SignatureValue has #{ signature_value_doc.size } octets (should have #{ pub_k.n.to_i.size } RSA modulus octets)"
      return false
    end
    signed_info_c14n_xml = signed_info_c14n( doc, sig_ns, prefix )

    signed_info_digest_calc = b64_enc( digest( sig_digest_algo, signed_info_c14n_xml ) )
    signed_info_digest_doc  = b64_enc( decode_sig_value( signature_value_doc, sig_digest_algo, pub_k ) )
    @messages << "SignedInfo Digest calc:    #{ signed_info_digest_calc } (SignatureMethod Algorithm=#{ sig_algo })"
    @messages << "SignedInfo Digest decoded: #{ signed_info_digest_doc  } (SignatureMethod Algorithm=#{ sig_algo })"

    return ( signed_info_digest_calc == signed_info_digest_doc )
  end

  def check_references( doc, sig_ns, prefix )
    check = true
    references = doc_references( doc, sig_ns, prefix )
    check = false if references.size == 0
    @messages << "Found #{ references.size } reference#{ references.size != 1 ? 's' : '' }"
    references.each do |ref|
      digest_algo = doc_reference_digest_method_algorithm( ref, sig_ns, prefix )
      digest_doc = doc_reference_digest_value( ref, sig_ns, prefix )
      if ref.attributes.size == 1 and ref.attributes[ 'URI' ]
        uri = ref.attributes[ 'URI' ].value
        case uri
        when ""
          ref_xml = strip_signature( doc.dup, sig_ns, prefix ).canonicalize
        else
          if uri =~ /^#ID_/
            ref_xml = extract_uri( doc, uri ).canonicalize
          else
            @messages << 'Reference URI not valid ❌'
            check = false
            next
          end
        end
        digest_calc = b64_enc( digest( digest_algo, ref_xml ) )
        @messages << "URI=#{ uri.empty? ? '""' : uri } Digest calc: #{ digest_calc } (DigestMethod Algorithm=#{ digest_algo })"
        @messages << "URI=#{ uri.empty? ? '""' : uri } Digest doc:  #{ digest_doc  } (DigestMethod Algorithm=#{ digest_algo })"
        if digest_calc == digest_doc
          @messages << 'Reference digest value correct'
        else
          @messages << 'Reference digest value not correct ❌'
          check = false
        end
      else
        # not reached if doc was validated against schema
        @messages << 'Reference has more than 1 attribute ❌'
      end
    end
    return check
  end

  def attribute_value( element, attr_name )
    element.attributes[ attr_name ].text
  end

  def doc_signature_method_algorithm( doc, sig_ns, prefix )
    signature_method_algorithm( attribute_value( doc.at_xpath( "//#{ prefix }:SignatureMethod", sig_ns ), 'Algorithm' ) )
  end

  def doc_references( doc, sig_ns, prefix )
    doc.xpath( "//#{ prefix }:SignedInfo/#{ prefix }:Reference", sig_ns )
  end

  def doc_reference_digest_method_algorithm( reference, sig_ns, prefix )
    digest_method_algorithm( attribute_value( reference.at_xpath( "#{ prefix }:DigestMethod", sig_ns ), 'Algorithm' ) )
  end

  def doc_reference_digest_value( reference, sig_ns, prefix )
    reference.at_xpath( "#{ prefix }:DigestValue", sig_ns ).text
  end

  def signed_info_c14n( doc, sig_ns, prefix )
    doc.at_xpath( "//#{ prefix }:SignedInfo", sig_ns ).canonicalize
  end

  def digest( hash_id, m )
    OpenSSL::Digest.new( hash_id, m ).digest
  end

  def signature_method_algorithm( id )
    {
      'http://www.w3.org/2000/09/xmldsig#rsa-sha1' => 'rsa-sha1',
      'http://www.w3.org/2001/04/xmldsig-more#rsa-sha256' => 'rsa-sha256'
    }[ id ]
  end

  def digest_method_algorithm( id )
    {
      'http://www.w3.org/2000/09/xmldsig#sha1' => 'sha1',
      'http://www.w3.org/2001/04/xmlenc#sha256' => 'sha256'
    }[ id ]
  end

  def emsa_pkcs1_v1_5_decode( hash_id, m )
    hash_size = digest( hash_id, '' ).size
    m[ m.size - hash_size, hash_size ]
  end

  # See rsa gem
  def os2ip( octet_string )
    octet_string.bytes.inject( 0 ) { |n, b| ( n << 8 ) + b }
  end

  # See rsa gem
  def i2osp( x, len = nil )
    raise ArgumentError, 'integer too large' if len && x >= 256 ** len
    StringIO.open do |buffer|
      while x > 0
        b = ( x & 0xFF ).chr
        x >>= 8
        buffer << b
      end
      s = buffer.string
      # FIXME
      if s.respond_to?( :force_encoding )
        s.force_encoding( Encoding::BINARY )
      end
      s.reverse!
      s = len ? s.rjust( len, "\0" ) : s
    end
  end

  # See rsa gem. note the bn modification here
  def modpow( base, exponent, modulus )
    result = 1
    while exponent > 0
      result = ( base * result ) % modulus unless ( ! exponent.bit_set? 0 )
      base = ( base * base ) % modulus
      exponent >>= 1
    end
    result
  end

  def rsavp1( pub_k, s )
    modpow( s, pub_k.e, pub_k.n )
  end

  def extract_certs( doc, sig_ns, prefix )
    certs = Array.new
    doc.xpath( "//#{ prefix }:X509Certificate", sig_ns ).each do |c|
      begin
        pem = pemify( c.text )
        certs << OpenSSL::X509::Certificate.new( pem )
      rescue Exception => e
        @messages << e.inspect
      end
    end
    certs
  end

  def pemify( string )
    [
      '-----BEGIN CERTIFICATE-----',
      string.gsub( /[\r ]+/, '' ).split( "\n" ).join.split( /(.{64})/ ).reject { |e| e.empty? },
      '-----END CERTIFICATE-----'
    ].flatten.join( "\n" )
  end

  def decode_sig_value( value, sig_digest_algo, pub_k )
    m = rsavp1( pub_k, os2ip( value ) )
    emsa_pkcs1_v1_5_decode( sig_digest_algo, i2osp( m, pub_k.n.to_i.size ) )
  end

  def strip_signature( doc, sig_ns, prefix )
    signature_element = doc.at_xpath( "//#{ prefix }:Signature", sig_ns )
    signature_element.remove
    doc
  end

  def extract_uri( doc, uri )
    # See kdms/kdm_19400_8a1ace55-3953-4a6a-9f74-becc1d42af69_97f83429b5258215db5f96e79c8cbb4c1f2c8c8d.xml,
    # a dolby KDM with prefixed children, like "etm:AuthenticatedPublic".
    # Iterating children to pick up uri because I don't know a simpler way for now
    requested_node_name = uri.split( '#ID_' ).last
    doc.root.children.each do |child|
      if child.node_name and child.node_name == requested_node_name
        prefix = child.namespace.prefix
        return doc.at_xpath( "//#{ prefix.nil? ? 'xmlns:' : prefix + ':' }#{ requested_node_name }[ @Id = '#{ uri[ 1 .. -1 ] }' ]" )
      end
    end
  end

  def b64_enc( octet_string )
    Base64.encode64( octet_string ).chomp
  end
  def b64_dec( string )
    Base64.decode64 string
  end

  def extract_signature_value( doc, sig_ns, prefix )
    b64_dec( doc.at_xpath( "//#{ prefix }:SignatureValue", sig_ns ).text.split( "\n" ).join )
  end

end # DC_Signature_Verification


class Eta
  attr_reader :percentage, :eta, :elapsed
  def initialize( title, width, looks_like, terminal_size, options, logger )
    @title = title
    @total = 100
    @scaling = width.to_f / @total
    @left, @major, @fill, @right = looks_like.scan( /./ )
    @terminal_size = terminal_size
    @output = logger
    @start = Time.now
  end

  def update( percentage )
    @percentage = percentage
    update_eta
  end

  def update_eta
    return if @percentage == 0
    @elapsed = Time.now - @start
    @eta = @elapsed * @total / @percentage - @elapsed
  end

  def update_terminal( percentage )
    update( percentage )
    line = bar
    if @terminal_size and line.length > @terminal_size[ :columns ]
      line = ' [...] ' + line[ line.length - @terminal_size[ :columns ] + 9 .. -1 ]
    end
    @output.cr( "%s\r" % line )
  end

  def clear_terminal
    @output.cr( "%s\r" % ( ' ' * bar.size ) )
  end

  def preserve_terminal
    @output.info ''
  end

  def preserve_terminal_title_with_message( message )
    clear_terminal
    @output.debug [ @title, message ].join( ' ' )
  end

  private

  def bar
    [ @title, percentage_pad, inner_bar, tail ].join( ' ' )
  end

  def percentage_pad
    "%3s%%" % @percentage
  end

  def inner_bar
    @left + @major * ( @percentage * @scaling ).ceil + @fill * ( ( @total - @percentage ) * @scaling ).floor + @right
  end

  def tail
    [ time_string( 'ETA', @eta ), time_string( 'Elapsed', @elapsed ) ].join( ' ' )
  end

  def time_string( head, t )
    return "%s --:--:--" % head if t.nil?
    t = t.to_i; s = t % 60; m  = ( t / 60 ) % 60; h = t / 3600
    "%s %02d:%02d:%02d" % [ head, h, m, s ]
  end
end # Eta


# FIXME ugh, this seems clonky
def command_exists?( command )
  ENV[ 'PATH' ].split( File::PATH_SEPARATOR ).any? { |d| File.exist? File.join( d, command ) }
end

def detect_terminal_size
  if command_exists?( 'tput' )
    { :columns => `tput cols`.to_i, :lines => `tput lines`.to_i }
  else
    nil
  end
end

def with_etabar( args, options, etabar_title, etabar_pbar_width, etabar_looks_like, logger, &block )
  eta = Eta.new( etabar_title, etabar_pbar_width, etabar_looks_like, detect_terminal_size, options, logger )
  chunks_per_percent = args.size / 100 + 1
  index = 0
  result = Array.new
  ( 0 .. 100 ).each do |percentage|
    chunks_per_percent.times do
      break if index == args.size
      result << yield( args[ index ] )
      index += 1
    end
    eta.update_terminal percentage
  end
  eta.preserve_terminal_title_with_message "Done"
  return result.reject { |e| e.nil? }
end

def digest_with_etabar( digest_algorithm, title, file, pbar_width, looks_like, options, logger )
  size = File.size file
  chunksize = 25000000 # had this at 4096 since forever which is ~30 times slower on my system -_-
  chunks = size / chunksize + ( size % chunksize > 0 ? 1 : 0 )
  chunks_per_percent = chunks / 100 + 1

  dgst = OpenSSL::Digest.new( digest_algorithm )
  io = File.open file
  eta = Eta.new( title, pbar_width, looks_like, detect_terminal_size, options, logger )

  ( 0 .. 100 ).each do |percentage|
    # read 1 % of chunks
    chunks_per_percent.times do
      chunk = io.read( chunksize )
      dgst.update chunk if chunk
    end
    eta.update_terminal percentage
  end

  return dgst.digest, eta
end

# lib/xml.rb
#
# FIXME
# Looking only at the first prefix returned from collect_all_namespaces_href_keys
# for a given namespace will fall on its nose when there would be multiple prefixes
# for the same namespace. E.g. I think in a Signature it would be entirely valid to
# use different prefixes for different portions, all evaluating to the same namespace.
#
# Good enough for now but ktfim
#
def namespace_prefix( doc, ns )
  doc_ns = doc.collect_all_namespaces_href_keys
  if doc_ns.key?( ns )
    doc_ns[ ns ].first.nil? ? 'xmlns' : doc_ns[ ns ].first
  else
    'xmlns'
  end
end

def validate_xml( xml, file )
  errors = Array.new
  asdcp_type = xml.root.node_name
  # find schema match
  case asdcp_type
    # special handling as DCSubtitle files are not namespaced
  when 'DCSubtitle'
    xsd_file = 'DCSubtitle.v1.mattsson.xsd'
  else
    case asdcp_type
    when 'AssetMap'
      # see fhg
      xsd_file = ( MStr::Schemas[ xml.namespaces[ 'xmlns' ] ] or MStr::Schemas[ xml.namespaces[ 'xmlns:am' ] ] )
    else
      xsd_file = ( MStr::Schemas[ xml.namespaces[ 'xmlns' ] ] )
    end
  end
  if xsd_file
    xsd = Nokogiri::XML::Schema( open File.join( XSDDir, xsd_file ) )
    validation_errors = xsd.validate( xml )
  else
    if xml.namespaces.empty?
      errors << "Could not determine Schema (no namespace provided) ❌"
      return false, errors
    else
      errors << "Could not determine Schema for #{ xml.namespaces.inspect } ❌"
      return false, errors
    end
  end
  if validation_errors.empty?
    return true, errors
  else
    validation_errors.each do |e|
      errors << "Schema check ❌: #{ File.basename xsd_file } #{ file } line #{ e.line }: #{ e }"
    end
    return false, errors
  end
end

def validation( errors, error_status, xml, source_file, id, type_indicator )
  valid, validation_errors = validate_xml( xml, source_file )
  if valid == false
    validation_errors.each do |e|
      errors << "#{ type_indicator } #{ id }: #{ e }"
      error_status = true
    end
  end
  return valid, errors, error_status
end

def check_signature( xml )
  signature_result = DC_Signature_Verification.new( xml )
end

def errors_signature_verification( errors, error_status, signature_result, id, file, type_indicator )
  if signature_result.signature_node.empty?
    return errors, error_status
  end
  if signature_result.verified?
    # While the signature might verify there could be problems
    # with dc specific certificate properties. Report those.
    if ! signature_result.crypto.errors[ :context ].values.flatten.empty?
      errors << "#{ type_indicator } #{ id }: Signature ❌: #{ signature_result.crypto.errors[ :context ].inspect }"
      error_status = true
    end
  else
    errors << "#{ type_indicator } #{ id }: Signature verification failure ❌:\n\t#{ signature_result.messages.join( "\n\t" ) }"
    error_status = true
  end
  return errors, error_status
end

# FIXME
# returns xml or false.
# in addition to xml all kinds of stuff will be examined here
# hence the hoopla to skip expected errors from non-xml.
# still: what an appalling method
def get_xml_of_type( asdcp_type, file, errors, errors_status )
  begin
    xml = Nokogiri::XML( open file )
  rescue Exception => e
    @logger.info "#{ file }: #{ e.message }"
    return false, errors, errors_status
  end

  unless xml.errors.empty?
    xml.errors.each do |error|
      # expected errors from non-xml
      next if error.message =~ /Start tag expected/ or error.message =~ /Document is empty/
      errors << "Syntax error ❌: #{ file }: #{ error }"
      errors_status = true
      @logger.info errors.last
    end
    return false, errors, errors_status
  end

  if xml.root
    case xml.root.node_name
    when asdcp_type
      return xml, errors, errors_status
    else
      return false, errors, errors_status
    end
  else
    return false, errors, errors_status
  end
end

def xml?( file )
  begin
    xml = Nokogiri::XML( open file )
  rescue Exception => e
    return false
  end
  if xml.root.nil?
    return false
  else
    xml
  end
end

# FIXME Rather brittle mechanism here. I'd like to have infrastructure types show up (CompositionPlaylist, PackingList, DCSubtitle, DCMetadata)
def get_asset_uuid( file )
  id = nil
  if File.exist?( file )
    xml = xml?( file )
    if xml
      xml.remove_namespaces!

      # FIXME how to find the first child level Id only?
      ids = xml.xpath( '//Id' )
      if ids.size > 0
        id = ids.first.text.split( ':' ).last
      else
        id = xml.xpath( '//SubtitleID' ).text # DCSubtitle
        if id.empty?
          id = xml.xpath( '//MetadataID' ).text # PCF, DCMetadata
        end
      end
      id = id.strip

    else # not xml
      meta = MxfTools.mxf_inspect( file )
      if meta
        id = meta[ 'AssetUUID' ]
      end
    end

  end
  return id
end

def element_text( xml, xpath_query, ns )
  text = xml.xpath( xpath_query, ns )
  if text.empty?
    nil
  else
    text
  end
end

def uuid_from_urn_scheme( string )
  string.split( 'urn:uuid:' ).last
end

# Returns subject, issuer and serial (from signing certificate) and x509serialnumber (from Signer..X509SerialNumber)
def signer_info( xml, sig )
  sig_info = Hash.new
  if ! sig.signature_node.empty?
    sig_info[ :signer_name ] = sig.signer_name
    sig_info[ :signer_issuer_name ] = sig.signer_issuer
    if ! sig.signer_node.empty?
      signer_ns_prefix = namespace_prefix( xml, MStr::Ns_Xmldsig )
      sig_info[ :x509serialnumber ] = sig.signer_node.first.xpath( "//#{ signer_ns_prefix }:X509SerialNumber", signer_ns_prefix => MStr::Ns_Xmldsig ).first.text.to_i
      sig_info[ :cert_serial ] = sig.crypto.context.first.serial.to_i unless sig.crypto.context.empty?
    end
  end
  return sig_info
end


def font?( file )
  fh = File.open( file, 'r' )
  magic = fh.read( 4 ).unpack( 'H*' ).first
  fh.close
  case magic
  when "00010000"
    MStr::TTF
  when "4f54544f"
    MStr::OTF
  else
    nil
  end
end


def confirm_or_create( location )
  testfile = File.join( location, rand.to_s )
  if File.exist?( location )
    begin
      result = FileUtils.touch( testfile )
      File.delete( testfile )
      return true
    rescue Exception => result
      return false
    end
  else
    begin
      result = FileUtils.mkdir_p( location )
      return true
    rescue Exception => result
      return false
    end
  end
end


# And the error goes to ...
def error_output
  where = Array.new
  where << 'below' if @logger.prints_errors
  where << 'with increased verbosity' if ! @logger.prints_errors
  where << "in autolog at #{ ENV[ 'DCP_INSPECT_DIR' ] }" if @logger.writes_autolog
  where << 'in autolog with option --autolog' if ! @logger.writes_autolog
  where << "in #{ @logger.logfile }" if @logger.writes_logfile
  where << 'in a logfile with option --logfile' if ! @logger.writes_logfile
  return where.join ' or '
end


def composition_summary_oneliner( composition_summary )
  "CPL #{ composition_summary[ :cpl_id ] }: Composition summary: " + [ [ :content_title_text, :type, :crypto, :spatiality, :aspect, :resolution, :picture_bitrate_avg, :duration, :edit_rate ].reject { |k| composition_summary[k].nil? }.map { |k| composition_summary[k] } ].join( ', ' )
end


# lib/cpl.rb
def cpl_inspect_xml( xml, dict, audio_stats, package_dir, composition_summaries, errors, hints, info, options )
  cpl_errors = false
  report = Array.new
  reels_report = Array.new
  cpl_referenced_assets = Array.new
  cpl_referenced_assets_encrypted = Array.new
  cpl_referenced_assets_encrypted_inferred_from_key_id = Array.new
  cpl_referenced_assets_types = Array.new
  cpl_reels_references_complete = Array.new

  ns = xml.collect_all_namespaces_href_keys
  @logger.dev "CPL all namespaces href keys: #{ ns }"
  cpl_ns = xml.root.namespace.href
  cpl_ns_prefix = namespace_prefix( xml, cpl_ns )
  cpl_id = xml.xpath( "/#{ cpl_ns_prefix }:CompositionPlaylist/#{ cpl_ns_prefix }:Id" ).text.split( ':' ).last
  cpl_file = package dict[ cpl_id ]

  case cpl_ns
  when MStr::Smpte_cpl
    cpl_type = 'SMPTE'
  when MStr::Interop_cpl
    cpl_type = 'Interop'
  else
    cpl_type = 'Unknown'
    errors << "CPL #{ cpl_id }: Default namespace unknown ❌: #{ cpl_ns }: #{ cpl_file }"
    errors << "CPL #{ cpl_id }: Default namespace unknown ❌: This might be a dcp_inspect bug. If you think it is ..."
    errors << "CPL #{ cpl_id }: Default namespace unknown ❌: ... please file an issue at https://github.com/wolfgangw/backports/issues/new"
    cpl_errors = true
  end
  cpl_referenced_assets_types << cpl_type

  # Check schema
  if options.validate
    begin
      valid, errors, cpl_errors = validation( errors, cpl_errors, xml, cpl_file, cpl_id, 'CPL' )
      report << "CPL #{ cpl_id }: Schema check: #{ valid ? 'OK ✅' : "Errors ❌ (See #{ error_output })" }"
    rescue Exception => e
      errors << "CPL #{ cpl_id }: Exception in Schema check ❌: #{ e.message }"
      cpl_errors = true
      report << errors.last
    end
  end

  # Check signature
  if @c14n_available
    signature_result = check_signature( xml )
    if signature_result.verified? and signature_result.crypto.errors[ :context ].values.flatten.empty?
      @signed_cpls_verified_count += 1
    end
    errors, cpl_errors = errors_signature_verification( errors, cpl_errors, signature_result, cpl_id, cpl_file, 'CPL' )
    report << "CPL #{ cpl_id }: #{ signature_result.messages.last }"
  else
    signature_result = nil
  end

  if signature_result and ! signature_result.signature_node.empty?
    @signed_cpls_count += 1
    sig_info = signer_info( xml, signature_result )
    report << "Signer:           #{ sig_info[ :signer_name ] }" if sig_info[ :signer_name ]
    report << "Signer issuer:    #{ sig_info[ :signer_issuer_name ] }" if sig_info[ :signer_issuer_name ]

    # Todo: Compare names in Signer and certificate
    #

    # Check Signer.X509Data.X509IssuerSerial info vs signer certificate
    # See e.g. dcp_2/V174* for a serial mismatch
    if ! signature_result.signer_node.empty? and sig_info[ :x509serialnumber ] and sig_info[ :cert_serial ]
      if sig_info[ :x509serialnumber ] != sig_info[ :cert_serial ]
        report << "Signer serial mismatch ❌: X509SerialNumber: #{ sig_info[ :x509serialnumber ] } Certificate: #{ sig_info[ :cert_serial ] }"
        errors << "CPL #{ cpl_id }: Signer serial mismatch ❌: X509SerialNumber: #{ sig_info[ :x509serialnumber ] } Certificate: #{ sig_info[ :cert_serial ] }"
        cpl_errors = true
      end
    else
      report << 'Signer info :x509serialnumber or :cert_serial could not be retrieved ❌'
      errors << "CPL #{ cpl_id }: Signer info :x509serialnumber or :cert_serial could not be retrieved ❌"
      cpl_errors = true
    end
  end

  # CPL:Id RFC-4122 compliant?
  if cpl_id !~ MStr::Uuid_rfc4122_re
    report << "CPL Id:           #{ cpl_id } [Not RFC-4122 compliant] ❌"
    errors << "CPL #{ cpl_id }: Value of CompositionPlaylist:Id is not RFC-4122 compliant ❌"
    cpl_errors = true
  else
    report << "CPL Id:           #{ cpl_id }"
  end

  report << "CPL file:         #{ cpl_file }"
  report << "CPL type:         #{ cpl_type } (#{ cpl_ns })"

  # Scrounge ContentTitleText
  content_title_text = xml.xpath( "/#{ cpl_ns_prefix }:CompositionPlaylist/#{ cpl_ns_prefix }:ContentTitleText" ).text
  if content_title_text.empty?
    report << "ContentTitleText: [Empty] ❌"
    errors << "CPL #{ cpl_id }: ContentTitleText is empty ❌"
  else
    report << "ContentTitleText: #{ content_title_text }"
  end

  begin
    if ( lang_aud_subs = content_title_text.split( '_' )[ 3 ].match /^[A-Z]{2,3}-[A-Za-z]{2,3}$/ )
      report << "\tLanguage audio and subtitles: #{ lang_aud_subs }"
    end
  rescue
  end

  annotation_text = xml.xpath( "/#{ cpl_ns_prefix }:CompositionPlaylist/#{ cpl_ns_prefix }:AnnotationText" ).text
  if annotation_text.empty?
    report << "AnnotationText:   [Empty]"
  else
    report << "AnnotationText:   #{ annotation_text }"
  end

  # Check ContentKind
  content_kind_nodeset = xml.xpath( "/#{ cpl_ns_prefix }:CompositionPlaylist/#{ cpl_ns_prefix }:ContentKind" )
  content_kind = content_kind_nodeset.text
  content_kind_scope_is_default = false
  if content_kind_nodeset.first
    content_kind_scope = content_kind_nodeset.first.attributes[ 'scope' ]
  end
  if content_kind.empty?
    hints << "CPL #{ cpl_id }: ContentKind is empty. May lead to display issues in player UIs"
    report << "ContentKind:      [Empty]"
  else
    if content_kind_scope
      if content_kind_scope.value == MStr::Cpl_content_kind_default_scope
        content_kind_scope_is_default = true
      else
        hints << "CPL #{ cpl_id }: ContentKind has non-standard scoped value #{ content_kind.inspect }. May lead to display issues in player UIs"
        report << "ContentKind:      #{ content_kind } [Non-standard scope #{ content_kind_scope.value.inspect }]"
      end
    else
      content_kind_scope_is_default = true
    end
    if content_kind_scope_is_default
      if MStr::Cpl_standard_content.include? content_kind
        report << "ContentKind:      #{ content_kind }"
      else
        hints << "CPL #{ cpl_id }: ContentKind has non-standard value #{ content_kind.inspect }. May lead to display issues in player UIs"
        report << "ContentKind:      #{ content_kind } [Non-standard value]"
      end
    end
  end

  # IssueDate
  issue_date = xml.xpath( "/#{ cpl_ns_prefix }:CompositionPlaylist/#{ cpl_ns_prefix }:IssueDate" )
  if issue_date
    if issue_date.text.empty?
      errors << "CPL #{ cpl_id }: IssueDate is empty ❌"
      cpl_errors = true
      report << "IssueDate:        [Empty -- See schema errors #{ error_output }] ❌"
    else
      begin
        issue_date_dt = DateTime.parse issue_date.text
        now_dt = DateTime.now
      rescue Exception => e
        errors << "CPL #{ cpl_id }: Can not parse IssueDate #{ issue_date.text.inspect } ❌"
        cpl_errors = true
      end
      if issue_date_dt
        if issue_date_dt >= now_dt
          info << "CPL #{ cpl_id }: Composition #{ content_title_text.empty? ? '[ContentTitleText empty]' : content_title_text.inspect } was issued in the future: IssueDate #{ issue_date.text.inspect } ahead of now (#{ now_dt.to_s }) by #{ distance_of_time_in_words( issue_date_dt, now_dt ) }"
        elsif issue_date_dt < now_dt
          info << "CPL #{ cpl_id }: Composition #{ content_title_text.empty? ? '[ContentTitleText empty] ❌' : content_title_text.inspect } was issued #{ distance_of_time_in_words( issue_date_dt, now_dt ) } ago"
        end
        issue_date_friendly = datetime_friendly( issue_date_dt )
        report << "IssueDate:        #{ issue_date.text } (#{ issue_date_friendly })"
      end
    end
  else
    report << "IssueDate:        [Not present -- See schema errors #{ error_output }]"
  end

  # TKR? (FIXME: Check URL scheme)
  issuer = xml.at_xpath( "/#{ cpl_ns_prefix }:CompositionPlaylist/#{ cpl_ns_prefix }:Issuer" )
  if issuer
    #
    # Interop and SMPTE UserText types -- used for Issuer -- are referred to by different names
    # Interop: 'lang' (see xsd/PROTO-ASDCP-CPL-20040511.xsd)
    # SMPTE: 'language' (see xsd/SMPTE-429-7-2006-CPL.xsd)
    #
    if ( issuer.attributes[ 'language' ] and issuer.attributes[ 'language' ].value == MStr::Tkr_attr ) or ( issuer.attributes[ 'lang' ] and issuer.attributes[ 'lang' ].value == MStr::Tkr_attr )
      report << "TKR Base URL:     #{ issuer.text }"
    else
      if issuer.text.empty?
        hints << "CPL #{ cpl_id }: Issuer is empty"
        report << 'Issuer:           [Empty]'
      else
        report << "Issuer:           #{ issuer.text }"
      end
    end
  else
    report << 'Issuer:           [Not present]'
  end

  # Creator
  creator = xml.xpath( "/#{ cpl_ns_prefix }:CompositionPlaylist/#{ cpl_ns_prefix }:Creator" )
  if creator
    if creator.text.empty?
      hints << "CPL #{ cpl_id }: Creator is empty"
      report << 'Creator:          [Empty]'
    else
      report << "Creator:          #{ creator.text }"
    end
  else
    report << 'Creator:          [Not present]'
  end

  #
  # Metadata // CMA
  # FIXME: For now this is merely a printout. We don't check against actual asset metadata
  #
  @logger.dev "CPL ns keys: #{ ns.keys }"
  if ( ns.keys & MStr::Composition_metadata_href ).any?
    cma_href_match = ( ns.keys & MStr::Composition_metadata_href ).first
    @logger.dev "CPL We have CompositionMetadataAsset: #{ cma_href_match }"
    cma = xml.xpath( '//meta:CompositionMetadataAsset/meta:*', 'meta' => cma_href_match )
    if cma
      report << 'CompositionMetadataAsset:'
      cma.each do |e|
        @logger.dev "                  #{ e.node_name }: #{ e.text.strip.gsub( /\n\s*/, ' ' ) }"
        report << "                  #{ e.node_name }: #{ e.text.strip.gsub( /\n\s*/, ' ' ) }"
      end
    end
  end

  # Reels
  reels = xml.xpath( "/#{ cpl_ns_prefix }:CompositionPlaylist/#{ cpl_ns_prefix }:ReelList/#{ cpl_ns_prefix }:Reel" )
  report << "Number of Reels:  #{ reels.size }"
  total_duration = 0
  composition_edit_rates = Array.new
  #
  # A composition can be "incomplete" in different ways:
  #   - referenced assets can exist outside of a given package (ok case)
  #   - referenced assets can be invalid/damaged/missing (fail case)
  # Collecting fail case id's in broken_assets to later on figure out
  # which case we're looking at.
  #
  broken_assets = Array.new
  reels_references = Array.new
  is_stereoscopic = Array.new # build a flag for naming convention checks
  composition_picture_aspect_ratios = Array.new
  composition_picture_resolutions = Array.new
  composition_picture_decomposition_levels = Array.new
  composition_picture_bitrates_max = Array.new
  composition_picture_bitrates_avg = Array.new
  composition_sound_channel_formats = Array.new
  composition_sound_channel_counts = Array.new
  composition_sound_samplerates = Array.new
  supplemental_refs = { :main_picture => 0, :main_sound => 0, :main_subtitle => 0, :main_caption => 0, :aux_data => 0 }

  reels.each_with_index do |reel, index|
    reel_no = index + 1
    cpl_reel = "CPL #{ cpl_id }: Reel #{ reel_no }"
    reels_report << "Reel #{ reel_no }:"
    reels_references[ index ] = Hash.new
    durations = Array.new
    edit_rates = Array.new
    assets_labels = Array.new
    assets = reel.xpath( "#{ cpl_ns_prefix }:AssetList/*" )

    # Check uniqueness of asset kinds which need to be unique in a reel.
    # Multiple instances of ClosedCaption, MainCaption and ClosedSubtitle allowed.
    asset_node_names = assets.collect { |a| a.node_name }
    assets_required_unique = asset_node_names - [ 'ClosedCaption', 'MainCaption', 'ClosedSubtitle' ]
    if assets_required_unique.uniq.size != assets_required_unique.size
      errors << "#{ cpl_reel }: Found duplicate asset kinds"
      cpl_errors = true
    end

    # Check a whole bunch of other things
    assets.each do |asset|

      #
      # CompositionMetadataAsset is already handled
      # Defer handling of MainMarkers to later on when we know reel duration
      #
      next if asset.node_name == 'CompositionMetadataAsset'

      # Collect reel referenced EssenceTypes (mainly to check for SMPTE reel completeness)
      case asset.node_name
      when 'MainPicture', 'MainStereoscopicPicture'
        reels_references[ index ][ :picture ] = true
      when 'MainSound'
        reels_references[ index ][ :sound ] = true
      when 'MainSubtitle'
        reels_references[ index ][ :subtitle ] = true
      when 'ClosedCaption'
        reels_references[ index ][ :caption ] = true
      end

      # Build a flag collection for naming convention checks: is_stereoscopic?
      case asset.node_name
      when 'MainPicture'
        is_stereoscopic[ index ] = false
      when 'MainStereoscopicPicture'
        is_stereoscopic[ index ] = true
      end

      asset_ns = asset.namespaces
      asset_id = asset.xpath( "#{ cpl_ns_prefix }:Id", asset_ns ).text.split( ':' ).last
      intrinsic_duration = asset.xpath( "#{ cpl_ns_prefix }:IntrinsicDuration", asset_ns ).text.to_i
      entry_point = asset.xpath( "#{ cpl_ns_prefix }:EntryPoint", asset_ns ).text.to_i
      duration = asset.xpath( "#{ cpl_ns_prefix }:Duration", asset_ns ).text.to_i
      if asset.xpath( "#{ cpl_ns_prefix }:KeyId", asset_ns )
        cpl_key_id = asset.xpath( "#{ cpl_ns_prefix }:KeyId", asset_ns ).text.split( ':' ).last
      else
        cpl_key_id = nil
      end

      # FIXME Timecode will die on edit_rate == 0
      cpl_asset_edit_rate_text = asset.xpath( "#{ cpl_ns_prefix }:EditRate", asset_ns ).text
      n, d = cpl_asset_edit_rate_text.split( ' ' ).map { |num| num.to_i }
      if n and d
        edit_rate = Rational( n, d ).to_f
      else
        edit_rate = nil
      end

      case asset.node_name
      when 'MainMarkers'
        # MainMarkers does not have Duration
      else
        durations << duration
      end
      edit_rates << edit_rate

      if dict
        if dict[ asset_id ]
          asset_file = package dict[ asset_id ]

          if File.exist?( asset_file )

            meta = MxfTools.mxf_inspect( asset_file )

            # MXF?
            if meta

              # Check asset Id for RFC-4122 compliance. All assets except DCSubtitle require this
              if asset_id !~ MStr::Uuid_rfc4122_re
                errors << "#{ cpl_reel }: Listed asset Id #{ asset_id } is not RFC-4122 compliant ❌"
                cpl_errors = true
              end

              # Get asset edit rate early
              begin
                n, d = ( meta[ 'EditRate' ] || meta[ 'SampleRate' ] ).split( '/' ).map { |num| num.to_i }
                asset_edit_rate = Rational( n, d ).to_f
              rescue Exception => e
                errors << "#{ cpl_reel }: Could not scrounge edit rate from #{ asset.node_name } asset #{ asset_id } ❌"
                cpl_errors = true
              end

              # Label types Interop/SMPTE
              case meta[ 'Label Set Type' ]
              when 'MXF Interop'
                cpl_referenced_assets << { asset_id => true }
                cpl_referenced_assets_types << MStr::AssetTypeInterop
              when 'SMPTE'
                cpl_referenced_assets << { asset_id => true }
                cpl_referenced_assets_types << MStr::AssetTypeSmpte
              else
                broken_assets << asset_id
                cpl_referenced_assets << { asset_id => false }
                cpl_referenced_assets_types << MStr::AssetTypeUnknown
              end

              # Encrypted essence?
              if meta[ 'EncryptedEssence' ]
                if meta[ 'EncryptedEssence' ] == 'Yes'
                  if meta[ 'CryptographicKeyID' ]
                    asset_key_id = meta[ 'CryptographicKeyID' ]
                    if asset_key_id == cpl_key_id
                      cpl_referenced_assets_encrypted << asset_id
                    else
                      case cpl_key_id
                      when nil
                        errors << "#{ cpl_reel }: #{ asset.node_name }: References encrypted asset but KeyId is [nil] ❌: #{ asset_id }"
                        cpl_errors = true
                      else
                        errors << "#{ cpl_reel }: #{ asset.node_name }: KeyId and CryptographicKeyID mismatch ❌: #{ asset_id }: #{ asset_file }"
                        cpl_errors = true
                      end
                    end
                  else
                    errors << "#{ cpl_reel }: #{ asset.node_name }: Could not read CryptographicKeyID in #{ asset_file } ❌"
                    cpl_errors = true
                  end
                end
              else
                errors << "#{ cpl_reel }: #{ asset.node_name }: Could not read EncryptedEssence Yes/No in #{ asset_file } ❌"
                cpl_errors = true
              end

              # IntrinsicDuration / EntryPoint / Duration sane?
              sane_IntrinsicDuration_EntryPoint_Duration = true
              if intrinsic_duration - entry_point < duration
                errors << "#{ cpl_reel }: Duration #{ duration } in #{ asset.node_name } does not compute ❌: IntrinsicDuration #{ intrinsic_duration } - EntryPoint #{ entry_point } < Duration #{ duration }"
                sane_IntrinsicDuration_EntryPoint_Duration = false
                cpl_errors = true
              end
              if entry_point >= intrinsic_duration
                exceed_frames = entry_point + 1 - intrinsic_duration
                errors << "#{ cpl_reel }: EntryPoint #{ entry_point } in #{ asset.node_name } exceeds IntrinsicDuration #{ intrinsic_duration } by #{ amount( 'frame', exceed_frames ) } ❌"
                sane_IntrinsicDuration_EntryPoint_Duration = false
                cpl_errors = true
              end
              if intrinsic_duration != meta[ 'ContainerDuration' ].to_i
                errors << "#{ cpl_reel }: IntrinsicDuration #{ intrinsic_duration } in #{ asset.node_name } does not match ContainerDuration #{ meta[ 'ContainerDuration' ].nil? ? '[NaN]' : meta[ 'ContainerDuration' ] } of asset #{ asset_id } ❌"
                cpl_errors = true
                if meta[ 'ContainerDuration' ].to_i - entry_point < duration
                  errors << "#{ cpl_reel }: Duration #{ duration } in #{ asset.node_name } does not compute ❌: ContainerDuration #{ meta[ 'ContainerDuration' ] } of asset #{ asset_id } - EntryPoint #{ entry_point } < Duration #{ duration }"
                  sane_IntrinsicDuration_EntryPoint_Duration = false
                  cpl_errors = true
                end
              end
              if sane_IntrinsicDuration_EntryPoint_Duration
                asset_snippet = [ 'ask', entry_point.to_s, duration.to_s ].join( '_' ).to_sym
              end

              # Check picture
              case asset.node_name
              when 'MainPicture', 'MainStereoscopicPicture'

                # decomposition levels
                if meta[ 'DecompositionLevels' ]
                  picture_decomposition_levels = meta[ 'DecompositionLevels' ].to_i
                  composition_picture_decomposition_levels << picture_decomposition_levels
                else
                  picture_decomposition_levels = nil
                  composition_picture_decomposition_levels << nil
                  errors << "#{ cpl_reel }: Expected to read image DecompositionLevels value but got nil ❌"
                  cpl_errors = true
                end

                # width and height
                picture_stored_width, picture_stored_height = meta[ 'StoredWidth' ], meta[ 'StoredHeight' ]
                picture_dimensions = "#{ picture_stored_width }x#{ picture_stored_height }"
                picture_aspect_ratio = ( picture_stored_width.to_f / picture_stored_height.to_f ).round( 3 )

                # avg and max bitrate
                if meta[ 'Max BitRate' ]
                  picture_bitrate_max_mbs = meta[ 'Max BitRate' ].split( ' ' )[0].to_f
                else
                  picture_bitrate_max_mbs = nil
                end
                if meta[ 'Average BitRate' ]
                  picture_bitrate_avg_mbs = meta[ 'Average BitRate' ].split( ' ' )[0].to_f
                else
                  picture_bitrate_avg_mbs = nil
                end

                # aspect ratio
                case picture_aspect_ratio
                when 1.896 # Full container
                  picture_aspect_ratio_moniker = 'C'
                when 1.85 # Flat
                  picture_aspect_ratio_moniker = 'F'
                when 2.387 # Scope
                  picture_aspect_ratio_moniker = 'S'
                when 1.778 # HD
                  picture_aspect_ratio_moniker = '16:9'
                  hints << "#{ cpl_reel }: #{ asset.node_name } has non-DCI aspect ratio #{ picture_aspect_ratio } (#{ picture_dimensions }, #{ picture_aspect_ratio_moniker }): Playback with proper non-standard masking recommended"
                else
                  picture_aspect_ratio_moniker = picture_aspect_ratio.to_s
                  hints << "#{ cpl_reel }: #{ asset.node_name } has non-DCI aspect ratio #{ picture_aspect_ratio } (#{ picture_dimensions }, #{ picture_aspect_ratio_moniker }): Playback with proper non-standard masking recommended"
                end
                composition_picture_aspect_ratios << picture_aspect_ratio

                # dimensions
                case picture_dimensions
                when '1998x1080', '2048x858', '2048x1080'
                  picture_dimensions_moniker = '2K'
                when '3996x2160', '4096x1716', '4096x2160'
                  picture_dimensions_moniker = '4K'
                when '1920x1080', '3840x2160'
                  picture_dimensions_moniker = 'HD' if picture_dimensions == '1920x1080'
                  picture_dimensions_moniker = 'UHD' if picture_dimensions == '3840x2160'
                  hints << "#{ cpl_reel }: #{ asset.node_name } has non-DCI pixel dimensions (#{ picture_dimensions }, #{ picture_dimensions_moniker })"
                else
                  picture_dimensions_moniker = picture_dimensions
                  errors << "#{ cpl_reel }: #{ asset.node_name } has non-DCI pixel dimensions (#{ picture_dimensions })"
                  cpl_errors = true
                end
                composition_picture_resolutions << picture_dimensions_moniker

                # FIXME wording: HFR is part of DCI/SMPTE
                # bitrate
                if picture_bitrate_max_mbs
                  if picture_bitrate_max_mbs > PictureBitrateMaxDCI
                    if picture_bitrate_max_mbs > PictureBitrateMaxHFR
                      errors << "#{ cpl_reel }: #{ asset.node_name } bitrate maximum #{ meta[ 'Max BitRate' ] } exceeds DCI and HFR maxima (#{ PictureBitrateMaxDCI } and #{ PictureBitrateMaxHFR } Mb/s) ❌"
                      cpl_errors = true
                    # FIXME
                    elsif picture_bitrate_max_mbs <= PictureBitrateMaxHFR
                      errors << "#{ cpl_reel }: #{ asset.node_name } bitrate maximum #{ meta[ 'Max BitRate' ] } exceeds DCI maximum (#{ PictureBitrateMaxDCI } Mb/s) ❌"
                      cpl_errors = true
                      hints << "#{ cpl_reel }: #{ asset.node_name } bitrate maximum #{ meta[ 'Max BitRate' ] } exceeds DCI maximum (#{ PictureBitrateMaxDCI } Mb/s). Playback might fail on DCI systems. Playback might work on HFR systems"
                    end
                  end
                  if picture_bitrate_max_mbs > PictureBitrateMaxDCISafe and picture_bitrate_max_mbs <= PictureBitrateMaxDCI
                    hints << "#{ cpl_reel }: #{ asset.node_name } bitrate maximum #{ meta[ 'Max BitRate' ] } exceeds suggested safe maximum #{ PictureBitrateMaxDCISafe } Mb/s. Playback might fail on DCI systems"
                  end
                end
                if picture_bitrate_avg_mbs
                  if picture_bitrate_avg_mbs > PictureBitrateMaxDCISafe and picture_bitrate_avg_mbs <= PictureBitrateMaxDCI
                    hints << "#{ cpl_reel }: #{ asset.node_name } bitrate average #{ meta[ 'Average BitRate' ] } exceeds suggested safe average #{ PictureBitrateMaxDCISafe } Mb/s. Playback might fail on DCI systems"
                  end
                end
                if sane_IntrinsicDuration_EntryPoint_Duration == true
                  composition_picture_bitrates_max << picture_bitrate_max_mbs
                  composition_picture_bitrates_avg << { :duration => duration, :picture_bitrate_avg_mbs => picture_bitrate_avg_mbs }
                end


              end # Check picture (MainPicture)


              # Check audio
              case asset.node_name
              when 'MainSound'

                # channel format
                if meta[ 'ChannelFormat' ]
                  audio_channel_format = meta[ 'ChannelFormat' ].to_i
                  composition_sound_channel_formats << audio_channel_format
                else
                  audio_channel_format = nil
                  composition_sound_channel_formats << nil
                  errors << "#{ cpl_reel }: Expected to read sound ChannelFormat but got nil ❌"
                  cpl_errors = true
                end

                # Sampling rate
                audio_sampling_rate = meta[ 'AudioSamplingRate' ]
                audio_sampling_rate_f = audio_sampling_rate.to_r.to_f
                if audio_sampling_rate != '48000/1' and audio_sampling_rate != '96000/1'
                  errors << "#{ cpl_reel }: MainSound sampling rate #{ audio_sampling_rate } Hz. Expected 48 kHz or 96 kHz ❌"
                  cpl_errors = true
                end

                # Bits per sample
                audio_quantization_bits = meta[ 'QuantizationBits' ].to_i
                if audio_quantization_bits != 24
                  errors << "#{ cpl_reel }: MainSound quantization #{ audio_quantization_bits } bps. Expected 24 bps ❌"
                  cpl_errors = true
                end

                # Channel configuration
                audio_channel_count = meta[ 'ChannelCount' ].to_i
                case audio_channel_count
                when 1, 3, 4, 5, 7
                  errors << "#{ cpl_reel }: MainSound has #{ amount( 'channel', audio_channel_count ) } ❌: Use 5.1, 7.1, 7.1DS or wild track (2.0 is expected to mostly work)"
                  cpl_errors = true
                  audio_channel_count_moniker = audio_channel_count.to_s
                when 2
                  hints << "#{ cpl_reel }: MainSound has 2 channels: Expected to mostly work. Use 5.1, 7.1, 7.1DS or wild track to make sure"
                  audio_channel_count_moniker = '20'
                when 6
                  audio_channel_count_moniker = '51'
                when 8
                  audio_channel_count_moniker = '71'
                when 12
                  audio_channel_count_moniker = '11.1'
                else
                  audio_channel_count_moniker = audio_channel_count.to_s
                end
                composition_sound_channel_counts << audio_channel_count_moniker

                # Block align
                audio_block_align = meta[ 'BlockAlign' ].to_i
                if audio_block_align != audio_channel_count * 3 # don't use audio_quantization_bits here -- anything other than 24 bps is an error
                  errors << "#{ cpl_reel }: MainSound has unexpected BlockAlign value #{ audio_block_align } ❌: Expected #{ audio_channel_count * 3 }: Check audio source"
                  cpl_errors = true
                end

                # Edit rate
                if asset_edit_rate != edit_rate
                  errors << "#{ cpl_reel }: MainSound EditRate #{ edit_rate } does not match asset EditRate #{ asset_edit_rate } ❌"
                  cpl_errors = true
                end

                # Audio characteristics (Levels, RMS, silent channels)
                audio_stats[ asset_id ] ||= Hash.new
                dkdms = Hash.new
                if options.audio_analysis
                  if sane_IntrinsicDuration_EntryPoint_Duration
                    audio_stats[ asset_id ][ asset_snippet ] ||= nil

                    if meta[ 'EncryptedEssence' ] == 'Yes'
                      if dkdms[ cpl_id ]
                        if dkdms[ cpl_id ][ asset_key_id ]
                          key = dkdms[ cpl_id ][ asset_key_id ]
                        else
                          hints << "#{ cpl_reel }: MainSound: Audio analysis requested but got no key for asset #{ asset_id }: Not yet implemented"
                          key = nil
                        end
                      else
                        hints << "#{ cpl_reel }: MainSound: Audio analysis requested but got no DKDM for CPL #{ cpl_id }: Not yet implemented"
                        key = nil
                      end
                    else
                      key = nil
                    end

                    if @dcp_inspect_temp
                      if audio_stats[ asset_id ][ asset_snippet ]
                        @logger.info "#{ cpl_reel }: Audio analysis: Seen #{ asset_id }:#{ entry_point }:#{ duration } before. Using previous result"
                      else
                        if key
                          audio_stats[ asset_id ][ asset_snippet ] = audio_characteristics( @dcp_inspect_temp, asset_file, audio_channel_count, entry_point, duration, key )
                        elsif meta[ 'EncryptedEssence' ] == 'No'
                          @logger.cr "#{ cpl_reel }: Audio analysis ..."
                          audio_stats[ asset_id ][ asset_snippet ] = audio_characteristics( @dcp_inspect_temp, asset_file, audio_channel_count, entry_point, duration, key )
                          @logger.info "#{ cpl_reel }: Audio analysis: Done"
                        end
                      end
                    else
                      hints << "#{ cpl_reel }: MainSound: Audio analysis requested but got no temp location to write to"
                    end

                  end
                end


              end # Check audio (MainSound)


              # This meta_report (and edit_rate) abomination below needs to go. Ugh
              meta_report = [
                meta[ 'Label Set Type' ] || 'Label Set Type:' + MStr::AssetTypeUnknown,
                meta[ 'ContainerDuration' ] ? meta[ 'EditRate' ] || meta[ 'SampleRate' ] ? Timecode.new( meta[ 'ContainerDuration' ].to_i, asset_edit_rate ).to_s : '[NaN]' : 'ContainerDuration:' + MStr::AssetTypeUnknown,
                meta[ 'EncryptedEssence' ] ? meta[ 'EncryptedEssence' ] == 'Yes' ? 'encrypted' : 'plaintext' : 'Encrypted:' + MStr::AssetTypeUnknown,
                asset.node_name =~ /Picture/ ? ( meta[ 'StoredWidth' ] || 'StoredWidth:' + MStr::AssetTypeUnknown ) + 'x' + ( meta[ 'StoredHeight' ] || 'StoredHeight:' + MStr::AssetTypeUnknown ) : '',
                asset.node_name =~ /Picture/ ? meta[ 'Average BitRate' ] ? 'avg ' + meta[ 'Average BitRate' ] : 'avg [NaN Mb/s]' : '',
                asset.node_name =~ /Picture/ ? meta[ 'Max BitRate' ] ? 'max ' + meta[ 'Max BitRate' ] : 'max [NaN Mb/s]' : '',
                asset.node_name =~ /Sound/ ?
                  ( meta[ 'ChannelCount' ].to_s + 'ch' || 'ChannelCount:' + MStr::AssetTypeUnknown ) + ' ' +
                  ( audio_sampling_rate == '48000/1' ? '48kHz' : audio_sampling_rate == '96000/1' ? '96kHz' : audio_sampling_rate ) + ' ' +
                  ( ( meta[ 'QuantizationBits' ] || 'QuantizationBits:' + MStr::AssetTypeUnknown ) + 'bps' )
                  : '',
                asset.node_name =~ /Sound/ ? audio_stats[ asset_id ] ? audio_stats[ asset_id ][ asset_snippet ] ? audio_stats[ asset_id ][ asset_snippet ][ :rms_lev_db ] ? "RMS #{ audio_stats[ asset_id ][ asset_snippet ][ :rms_lev_db ][ :overall ] } dBFS" + ' ' + bars( audio_stats[ asset_id ][ asset_snippet ][ :rms_lev_db ][ :channels ] ) : '[FAIL]' : '' : '' : '',
                asset.node_name =~ /Sound/ ? audio_stats[ asset_id ] ? audio_stats[ asset_id ][ asset_snippet ] ? audio_stats[ asset_id ][ asset_snippet ][ :pk_lev_db ] ? "Peak #{ audio_stats[ asset_id ][ asset_snippet ][ :pk_lev_db ][ :overall ] } dBFS" + ' ' + bars( audio_stats[ asset_id ][ asset_snippet ][ :pk_lev_db ][ :channels ] ) : '[FAIL]' : '' : '' : '',
                meta[ 'EssenceType' ] || 'EssenceType:' + MStr::AssetTypeUnknown
              ].reject { |e| e.nil? or e.empty? }.join( ', ' )

            else

              # DCSubtitle?
              xml, errors, cpl_errors = get_xml_of_type( 'DCSubtitle', asset_file, errors, cpl_errors )
              if xml

                cpl_referenced_assets << { asset_id => true }
                cpl_referenced_assets_types << MStr::AssetTypeInterop

                #
                # DCSubtitle Schema validation
                #
                if options.validate
                  begin
                    valid, errors, cpl_errors = validation( errors, cpl_errors, xml, asset_file, asset_id, 'DCSubtitle' )
                    report << "#{ cpl_reel }: DCSubtitle #{ asset_id }: Schema check: #{ valid ? 'OK ✅' : "Errors ❌ (See #{ error_output })" }"
                  rescue Exception => e
                    errors << "#{ cpl_reel }: DCSubtitle #{ asset_id }: Exception in Schema check ❌: #{ e.message }"
                    cpl_errors = true
                    report << errors.last
                  end
                end

                #
                # Check for content of ReelNumber element
                #
                if ( reelnumber_el = xml.xpath( '/DCSubtitle/ReelNumber' ) and reelnumber_el.size == 1 )
                  if reelnumber_el.children.size == 1
                    if reelnumber_el.children.first.class == Nokogiri::XML::Text
                      reelnumber_el_content = reelnumber_el.children.first.content
                      if reelnumber_el_content =~ /\s*?\d+\s*?/
                        if reelnumber_el_content.to_i != reel_no
                          hints << "#{ cpl_reel }: DCSubtitle #{ asset_id }: ReelNumber '#{ reelnumber_el_content.to_i }' does not match its CPL reel number '#{ reel_no }'"
                          report << hints.last
                        end
                      else
                        hints << "#{ cpl_reel }: DCSubtitle #{ asset_id }: ReelNumber content is not numerical: #{ reelnumber_el_content.inspect }"
                        report << hints.last
                      end
                    else
                      errors << "#{ cpl_reel }: DCSubtitle #{ asset_id }: ReelNumber has unexpected content ❌: #{ reelnumber_el.children.first.class }"
                      cpl_errors = true
                      report << errors.last
                    end
                  else
                    if reelnumber_el.children.size == 0
                      hints << "#{ cpl_reel }: DCSubtitle #{ asset_id }: ReelNumber has no content"
                      report << hints.last
                    elsif reelnumber_el.children.size > 1 # Note that TI's DTD says CDATA (non-parsed character data)
                      hints << "#{ cpl_reel }: DCSubtitle #{ asset_id }: ReelNumber has more than 1 subelement"
                      report << hints.last
                    end
                  end
                else
                  if reelnumber_el.size == 0
                    errors << "#{ cpl_reel }: DCSubtitle #{ asset_id }: ReelNumber element not found ❌"
                    cpl_errors = true
                    report << errors.last
                  else
                    errors << "#{ cpl_reel }: DCSubtitle #{ asset_id }: More than 1 ReelNumber element found ❌"
                    cpl_errors = true
                    report << errors.last
                  end
                end

                #
                # Check for content of Language element
                #
                if ( language_el = xml.xpath( '/DCSubtitle/Language' ) and language_el.size == 1 )
                  if language_el.children.size == 1
                    if language_el.children.first.class == Nokogiri::XML::Text
                      language_el_content = language_el.children.first.content
                      if language_el_content =~ /\s*?[:alpha:]\s*?/
                        #
                      else
                        hints << "#{ cpl_reel }: DCSubtitle #{ asset_id }: Language content contains unexpected characters: #{ language_el_content.inspect }"
                        report << hints.last
                      end
                    else
                      errors << "#{ cpl_reel }: DCSubtitle #{ asset_id }: Language has unexpected content ❌: #{ language_el.children.first.class }"
                      cpl_errors = true
                      report << errors.last
                    end
                  else
                    if language_el.children.size == 0
                      hints << "#{ cpl_reel }: DCSubtitle #{ asset_id }: Language has no content"
                      report << hints.last
                    elsif language_el.children.size > 1 # Note that TI's DTD says CDATA (non-parsed character data)
                      hints << "#{ cpl_reel }: DCSubtitle #{ asset_id }: Language has more than 1 subelement"
                      report << hints.last
                    end
                  end
                else
                  if language_el.size == 0
                    errors << "#{ cpl_reel }: DCSubtitle #{ asset_id }: Language element not found ❌"
                    cpl_errors = true
                    report << errors.last
                  else
                    errors << "#{ cpl_reel }: DCSubtitle #{ asset_id }: More than 1 Language element found ❌"
                    cpl_errors = true
                    report << errors.last
                  end
                end

                xml.remove_namespaces!
                if ( subtitles = xml.xpath( '//Subtitle' ) and subtitles.size > 0 )

                  #
                  # Check for TC range violations
                  #
                  subtitles.each do |sub|
                    [ 'TimeIn', 'TimeOut' ].each do |tc_attr_name|
                      tc_string = sub.attributes[ tc_attr_name ].value
                      begin
                        tc = parse_dcsubtitle_tc_string( tc_string, edit_rate )
                      rescue Exception => e
                        spot_number = ( sub.attributes[ 'SpotNumber' ] ? sub.attributes[ 'SpotNumber' ].value : nil )
                        errors << "#{ cpl_reel }: DCSubtitle #{ asset_id }: Spot #{ spot_number }: #{ e.inspect }"
                      end
                    end
                  end

                  #
                  # Scan all subtitles to find actual first_time_in and last_time_out
                  # Last subtitle is not necessarily the last displayed
                  # Scrounge content snippets along the way
                  #
                  # See CRAWL which sports empty Subtitle elements
                  #
                  # TI spec 2.9 Subtitle says
                  #
                  #   "The Subtitle element is a parent element. It includes [...] one or more child elements [...]"
                  #
                  # The XSD we're using right now (DCSubtitle.v1.mattsson.xsd), though, has
                  #
                  #     <xs:choice minOccurs="0" maxOccurs="unbounded">
                  #       <xs:element minOccurs="0" maxOccurs="unbounded" ref="Font"/>
                  #       <xs:element minOccurs="0" maxOccurs="unbounded" ref="Text"/>
                  #       <xs:element ref="Image"/>
                  #     </xs:choice>
                  #
                  # Correctness tbd
                  #
                  # First
                  #
                  first_time_in = subtitles.first.attributes[ 'TimeIn' ].value
                  nodeset = subtitles.first.xpath( '*/Text|Text|*/Image|Image' )
                  if nodeset.empty?
                    first_time_in_text = '[No child element]'
                    hints << "#{ cpl_reel }: DCSubtitle #{ asset_id }: First Subtitle element has neither Text nor Image"
                  else
                    first_time_in_text = truncate( nodeset.first.text.gsub( /^\s+|\s+$/, '' ), 3 ) # first line
                  end
                  subtitles[ 1 .. -1 ].each do |sub|
                    if first_time_in < sub.attributes[ 'TimeIn' ].value
                      break
                    end
                    first_time_in = sub.attributes[ 'TimeIn' ].value
                  end
                  #
                  # Last
                  #
                  last_time_out = subtitles.last.attributes[ 'TimeOut' ].value
                  nodeset = subtitles.last.xpath( '*/Text|Text|*/Image|Image' )
                  if nodeset.empty?
                    last_time_out_text = '[No child element]'
                    hints << "#{ cpl_reel }: DCSubtitle #{ asset_id }: Last Subtitle element has neither Text nor Image"
                  else
                    last_time_out_text = truncate( nodeset.last.text.gsub( /^\s+|\s+$/, '' ), 3 )
                  end
                  subtitles.reverse[ 1 .. -1 ].each do |sub|
                    if last_time_out > sub.attributes[ 'TimeOut' ].value
                      break
                    end
                    last_time_out = sub.attributes[ 'TimeOut' ].value
                    nodeset = sub.xpath( '*/Text|Text|*/Image|Image' )
                    if nodeset.empty?
                      last_time_out_text = '[No child element]'
                      hints << "#{ cpl_reel }: DCSubtitle #{ asset_id }: Last to-be-displayed Subtitle element has neither Text nor Image"
                    else
                      last_time_out_text = truncate( nodeset.last.text.gsub( /^\s+|\s+$/, '' ), 3 ) # last line
                    end
                  end

                  begin
                    first_time_in = parse_dcsubtitle_tc_string( first_time_in, edit_rate )
                    last_time_out = parse_dcsubtitle_tc_string( last_time_out, edit_rate )
                  rescue Exception => e
                    errors << "#{ cpl_reel }: DCSubtitle #{ asset_id }: Timecode: #{ e.message } ❌"
                    cpl_errors = true
                  end

                  #
                  # Cross-check duration/reel duration and last TimeOut
                  # We don't have reel_duration yet so here's an indirect way to tell if something's wrong
                  # FIXME
                  # Boy-oh-boy, this an ugly hack which exposes nicely the essential design flaw
                  #
                  # duration (self) and last TimeOut
                  #
                  if last_time_out.to_i > duration
                    errors << "#{ cpl_reel }: DCSubtitle #{ asset_id }: Last TimeOut #{ last_time_out.to_s } exceeds MainSubtitle duration #{ Timecode.new( duration, edit_rate ).to_s } ❌"
                    cpl_errors = true
                  end
                  #
                  # reel duration (preliminary) and last TimeOut
                  #
                  if durations.size > 1 # Assume we have one previous asset duration
                    begin
                      reel_duration_prelim = Timecode.new( durations[ 0 .. -2 ].min, edit_rates[ 0 .. -2 ].min )
                      if last_time_out > reel_duration_prelim
                        errors << "#{ cpl_reel }: DCSubtitle #{ asset_id }: Last TimeOut #{ last_time_out.to_s } exceeds reel duration #{ reel_duration_prelim } ❌"
                        cpl_errors = true
                      end
                    rescue Exception => e
                      errors << "#{ cpl_reel }: DCSubtitle #{ asset_id }: Timecode: #{ e.message }"
                      cpl_errors = true
                    end
                  end


                  #
                  # Check for empty elements. Thanks to Mattias Mattsson, Lilian Lefranc and Johann Hohenwarter for the field feedback
                  #
                  empty_subtitles = 0
                  subtitles.each do |sub|
                    spot_number = ( sub.attributes[ 'SpotNumber' ] ? sub.attributes[ 'SpotNumber' ].value : nil )
                    if sub.children.empty? or ( sub.children.size == 1 and sub.children.first.is_a? Nokogiri::XML::Text )
                      empty_subtitles += 1
                      errors << "#{ cpl_reel }: DCSubtitle: Empty Subtitle element#{ spot_number ? ': SpotNumber ' + spot_number : '' } ❌"
                      cpl_errors = true
                    elsif ( nodeset = sub.xpath( '*/Text|Text|*/Image|Image' ) )
                      nodeset.each do |node|
                        if node.text == ''
                          empty_subtitles += 1
                          hints << "#{ cpl_reel }: DCSubtitle: Empty #{ node.name } element#{ spot_number ? ': SpotNumber ' + spot_number : '' }. While not a specification error this can lead to playback problems in the field. Consider fixing"
                        end
                      end
                    end
                  end

                  #
                  # Check whether all referenced resources (font, subtitle images)
                  # are in the dictionary and exist on the medium
                  #
                  text_elements = false
                  text_elements_values = Array.new
                  image_elements = false
                  load_font_el = xml.xpath( '//LoadFont' )
                  font_el = xml.xpath( '//Font' )

                  subtitles.each do |sub|
                    spot_number = ( sub.attributes[ 'SpotNumber' ] ? sub.attributes[ 'SpotNumber' ].value : nil )
                    nodeset = sub.xpath( '*/Text|Text|*/Image|Image' )
                    nodeset.each do |node|
                      case node.name
                      when 'Text'
                        text_elements = true
                        text_elements_values << { :number => spot_number, :text => node.text.gsub( /^\s+|\s+$/, '' ) }
                      when 'Image'
                        image_elements = true
                        unless node.text.empty? # Checked above
                          asset_name = File.join( asset_id, node.text )
                          asset_pick = dict.select { |k, v| v =~ Regexp.new( asset_name ) }

                          if asset_pick.empty?
                            errors << "#{ cpl_reel }: DCSubtitle: #{ spot_number ? 'SpotNumber ' + spot_number + ': ' : '' }Referenced subtitle image #{ asset_name.inspect } not in AssetMap"
                            cpl_errors = true
                          else
                            unless File.exist?( package asset_pick.values.first ) # FIXME
                              errors << "#{ cpl_reel }: DCSubtitle: #{ spot_number ? 'SpotNumber ' + spot_number + ': ' : '' }Referenced subtitle image #{ asset_name.inspect } not found on the medium"
                              cpl_errors = true
                            end
                          end

                        end
                      end
                    end
                  end

                  # Check referenced font file
                  if text_elements
                    if load_font_el.empty?
                      hints << "#{ cpl_reel }: DCSubtitle: No LoadFont element found. Playback will use a default font"
                    else
                      load_font_uri = load_font_el.first.attributes[ 'URI' ].value
                      font_asset = File.join( asset_id, File.basename( load_font_uri ) )
                      font_path = nil
                      if dict.values.any? { |val| val =~ /#{ font_asset }$/ && font_path = val }
                        font_asset = package font_path
                        if File.exist?( font_asset )
                          if font?( font_asset )
                            # Check for font max size recommendation
                            font_asset_size = File.size font_asset
                            if font_asset_size > 655360 # 640 KB
                              errors << "#{ cpl_reel }: DCSubtitle: Font #{ font_asset } size #{ font_asset_size.to_k } exceeds 640 KB ❌"
                              cpl_errors = true
                            end
                            # Get font name
                            begin
                              # Scrounge font subfamily name
                              font_fu = TTFunk::File.open font_asset
                              begin
                                font_unique_subfamily = font_fu.name.unique_subfamily[ 1 ].to_s # FIXME not always 2nd element. Why/how?
                                info << "#{ cpl_reel }: DCSubtitle: Referenced font subfamily: #{ font_unique_subfamily }"
                              rescue TypeError => e
                                hints << "#{ cpl_reel }: DCSubtitle: Referenced font #{ font_asset }: Failed to extract internal name structure"
                              end

                              # Check if all glyphs can be rendered with provided font
                              glyphs_missing = false
                              text_elements_values.each do |spot|
                                unless font_fu.provides_glyphs_for?( spot[ :text ] )
                                  glyphs_missing = true
                                  # pick the exact ones
                                  glyphs_missing_list = Array.new
                                  spot[ :text ].split( '' ).each do |char|
                                    glyphs_missing_list << char unless font_fu.provides_glyphs_for?( char )
                                  end
                                  hints << "#{ cpl_reel }: DCSubtitle: SpotNumber #{ spot[ :number ] }: Font is missing #{ amount( 'glyph', glyphs_missing_list ) } to render #{ spot[ :text ].inspect } (#{ spot[ :text ].encoding }) ❌: #{ glyphs_missing_list.inspect }"
                                end
                              end
                              if glyphs_missing
                                hints << "#{ cpl_reel }: DCSubtitle: Font #{ font_asset } is missing some required glyphs ❌"
                              end
                            rescue NoMethodError => e
                              errors << "#{ cpl_reel }: DCSubtitle: Referenced font #{ font_asset } not valid ❌: #{ e.message }"
                              cpl_errors = true
                            end
                          else
                            errors << "#{ cpl_reel }: DCSubtitle: Font #{ font_asset } referenced in LoadFont is neither #{ MStr::TTF } nor #{ MStr::OTF } ❌"
                            cpl_errors = true
                          end
                        end
                      else
                        errors << "#{ cpl_reel }: DCSubtitle: Referenced font #{ font_asset } not in AssetMap ❌"
                        cpl_errors = true
                      end
                      if load_font_el.size > 1
                        hints << "#{ cpl_reel }: DCSubtitle: Found multiple LoadFont elements. Playback will use 1st: #{ load_font_uri }"
                      end
                    end
                  end

                  # Check LoadFont / Font Id dependency
                  # See https://github.com/wolfgangw/digital_cinema_tools_distribution/issues/15 for discussion
                  # TI's Subtitle_Specification_TI_1.1.pdf: Font's attributes are all #IMPLIED (not required)
                  font_ids = Array.new
                  font_el.each do |el|
                    font_ids << el.attributes[ 'Id' ].value if el.attributes[ 'Id' ]
                  end
                  font_ids.uniq!
                  if font_ids.size > 1
                    errors << "#{ cpl_reel }: DCSubtitle: Multiple Font Ids referenced ❌: #{ font_ids.inspect }"
                    cpl_errors = true
                  end
                  if load_font_el.empty?
                    if font_ids.size > 0
                      errors << "#{ cpl_reel }: DCSubtitle: No Font Id declared via LoadFont but referenced Font Ids found ❌: #{ font_ids.inspect }"
                      cpl_errors = true
                    end
                  else
                    if load_font_el.first.attributes[ 'Id' ]
                      load_font_id = load_font_el.first.attributes[ 'Id' ].value
                      font_ids.each do |font_id|
                        if font_id != load_font_id
                          errors << "#{ cpl_reel }: DCSubtitle: Referenced font Id '#{ font_id }' does not match the Id '#{ load_font_id }' declared in LoadFont. Font cannot be loaded ❌"
                          cpl_errors = true
                        end
                      end
                    end
                  end

                  #
                  # Check DCSubtitle's edit rate and nag about non-24-fps rates
                  #
                  if edit_rate != 24.0
                    hints << "#{ cpl_reel }: DCSubtitle: EditRate != 24 fps: #{ edit_rate } fps. Playback may fail"
                  end

                  # DCSubtitle meta report
                  meta_report = "DCSubtitle, #{ amount( 'subtitle', subtitles.to_a ) }, #{ first_time_in } '#{ first_time_in_text.nil? ? '[nil]' : first_time_in_text }' - #{ last_time_out } '#{ last_time_out_text.nil? ? '[nil]' : last_time_out_text }'#{ empty_subtitles > 0 ? ' Error: ' + empty_subtitles.to_s + ' empty Subtitle element' + ( empty_subtitles > 1 ? 's' : '' ) : '' }"

                else
                  meta_report = 'DCSubtitle, no Subtitle found'
                end
                meta = { 'EssenceType' => MStr::Timed_text }

              else # No meta and not DCSubtitle either

                broken_assets << asset_id
                cpl_referenced_assets << { asset_id => false }
                cpl_referenced_assets_types << MStr::AssetTypeUnknown
                meta_report = 'File found but not AS-DCP MXF ❌'

                # We don't have meta. Infer encryption from presence of KeyId
                if cpl_key_id
                  cpl_referenced_assets_encrypted_inferred_from_key_id << asset_id
                end

              end
            end

          else # Asset file does not exist

            broken_assets << asset_id
            cpl_referenced_assets << { asset_id => false }
            cpl_referenced_assets_types << MStr::AssetTypeUnknown
            meta_report = "Referenced asset file missing ❌: #{ dict[ asset_id ] }"

            # Infer encryption from presence of KeyId
            if cpl_key_id
              cpl_referenced_assets_encrypted_inferred_from_key_id << asset_id
            end

          end # File.exist?

        else # ok case: Supplemental/VF/External

          case asset.node_name
          when 'MainMarkers'
            markers = asset.xpath( "#{ cpl_ns_prefix }:MarkerList/#{ cpl_ns_prefix }:Marker", asset_ns )
            markers.each do |marker|
              label = marker.xpath( "#{ cpl_ns_prefix }:Label" ).text
            end
            @logger.dev "CPL We have MainMarkers"
            meta_report = "We have MainMarkers"
          else

            cpl_referenced_assets << { asset_id => false }
            cpl_referenced_assets_types << MStr::AssetTypeUnknown
            meta_report = 'Referenced asset file not listed in Assetmap dictionary: Supplemental/VF/External'
            hints << "#{ cpl_reel }: #{ asset.node_name }: #{ meta_report }"
            case asset.node_name
            when 'MainPicture', 'MainStereoscopicPicture'
              supplemental_refs[ :main_picture ] += 1
            when 'MainSound'
              supplemental_refs[ :main_sound ] += 1
            when 'MainSubtitle'
              supplemental_refs[ :main_subtitle ] += 1
            when 'MainCaption'
              supplemental_refs[ :main_caption ] += 1
            when 'AuxData'
              supplemental_refs[ :aux_data ] += 1
            end

            # Infer encryption from presence of KeyId
            if cpl_key_id
              cpl_referenced_assets_encrypted_inferred_from_key_id << asset_id
            end

          end

        end # if dict[ asset_id ]
      end # if dict

      begin
        reels_report << "#{ "%6s" % duration }  #{ edit_rate.nil? ? 'EditRate funk' : Timecode.new( duration, edit_rate ) } @ #{ edit_rate }  Entry #{ Timecode.new( entry_point, edit_rate ) }  #{ asset_id.split( '-' ).first }  #{ asset.node_name }\t(#{ meta_report })"
      rescue Exception => e
        errors << "#{ cpl_reel }: Duration #{ duration }: EditRate #{ edit_rate }: #{ e.message }"
        cpl_errors = true
      end

      if meta
        @logger.dev "#{ asset.node_name }: #{ asset_file } #{ asset.namespaces }"
        case asset.node_name
        when 'MainStereoscopicPicture'
          unless meta[ 'EssenceType' ] == MStr::Stereoscopic_pictures
            reels_report << "Essence type mismatch ❌: Expected MainStereoscopicPicture, got #{ meta[ 'EssenceType' ] || '[nil]' }"
            errors << "#{ cpl_reel }: " + reels_report.last
            cpl_errors = true
          end
        when 'MainPicture'
          unless ( meta[ 'EssenceType' ] == MStr::Pictures or meta[ 'EssenceType' ] == MStr::Mpeg2 )
            reels_report << "Essence type mismatch ❌: Expected MainPicture, got #{ meta[ 'EssenceType' ] || '[nil]' }"
            errors << "#{ cpl_reel }: " + reels_report.last
            cpl_errors = true
          end
        when 'MainSound'
          unless meta[ 'EssenceType' ] == MStr::Audio
            reels_report << "Essence type mismatch ❌: Expected MainSound, got #{ meta[ 'EssenceType' ] || '[nil]' }"
            errors << "#{ cpl_reel }: " + reels_report.last
            cpl_errors = true
          end
        when 'MainSubtitle'
          unless meta[ 'EssenceType' ] == MStr::Timed_text
            reels_report << "Essence type mismatch ❌: Expected MainSubtitle, got #{ meta[ 'EssenceType' ] || '[nil]' }"
            errors << "#{ cpl_reel }: " + reels_report.last
            cpl_errors = true
          end
        end
      end

    end # assets.each

    # Check reel's editrate sanity
    if edit_rates.uniq.size != 1
      reels_report << "\tEditRate mismatch ❌"
      composition_edit_rates << edit_rates.max
      errors << "#{ cpl_reel }: EditRate mismatch ❌"
      cpl_errors = true
    else
      composition_edit_rates << edit_rates.min
    end

    # Check reel's duration sanity
    if durations.uniq.size != 1
      reels_report << "\tDuration mismatch ❌"
      errors << "#{ cpl_reel }: Duration mismatch ❌: #{ durations.inspect }"
      cpl_errors = true
    else
      reel_duration = durations.first / edit_rates.min # seconds. gets it done but ugh
      total_duration += durations.first # frames
      if edit_rates.min > 0 and reel_duration < 1
        reels_report << "\tReel duration less than 1 second ❌"
        errors << "#{ cpl_reel }: Reel duration less than 1 second (#{ "%0.3f" % reel_duration } seconds, #{ amount( 'frame', durations.first.to_i ) }@#{ edit_rates.min } fps) ❌"
        cpl_errors = true
      elsif edit_rates.min > 0 and reel_duration < 5 # Doremi TB 65 (2010-03-09)
        hints << "#{ cpl_reel }: Reel duration less than 5 seconds. Doremi TB 65 suggests a 5 second minimum for safe playback on Doremi systems"
      end
    end

  end # reels loop

  # Setup composition summary one-liner
  composition_summary = Hash.new
  composition_summary[ :cpl_id ] = cpl_id
  composition_summary[ :content_title_text ] = content_title_text.inspect


  # Composition duration
  if composition_edit_rates.uniq.size == 1
    composition_edit_rate = composition_edit_rates.first
  else
    composition_edit_rate = 0
  end
  reels_report << 'Total duration:'
  begin
    total_duration_tc = Timecode.new( total_duration, composition_edit_rate )
  rescue Exception => e
    errors << "CPL #{ cpl_id }: Exception in reel report ❌: #{ e.message }"
  end
  if composition_edit_rate == 0
    cpl_errors = true
  end
  reels_report << "#{ "%6s" % total_duration }  #{ composition_edit_rate == 0 ? 'EditRate funk' : total_duration_tc } @ #{ composition_edit_rate }" # FIXME edit_rate
  if total_duration_tc
    composition_summary[ :duration ] = total_duration_tc.to_s
    composition_summary[ :edit_rate ] = "#{ composition_edit_rate } fps"
  else
    composition_summary[ :duration ] = '[Duration does not compute] ❌'
  end

  # Cosmetics: Interleave reels_report
  reels_report.each do |rp|
    report << rp
  end

  # Composition type SMPTE/Interop/Undetermined?
  assets_status_list = cpl_referenced_assets.map { |e| e.values }.flatten
  if cpl_referenced_assets_types.uniq.size == 1 and assets_status_list.uniq.size == 1 and assets_status_list.uniq.first == true
    composition_type = cpl_referenced_assets_types.uniq.first
    composition_summary[ :type ] = composition_type
  else
    # FIXME Composition type Mixed error or hint?
    composition_type = ( cpl_referenced_assets_types.include?( MStr::AssetTypeUnknown ) ? MStr::AssetTypeUndetermined : assets_status_list.include?( false ) ? MStr::AssetTypeUndetermined : MStr::AssetTypeMixed )
    composition_summary[ :type ] = composition_type
    if broken_assets.size != 0
      errors << "CPL #{ cpl_id }: Composition type ❌: #{ composition_type }"
      cpl_errors = true
    else
      hints << "CPL #{ cpl_id }: Composition type: #{ composition_type }: Supplemental/VF/External"
    end
  end

  # Composition requires KDM?
  if cpl_referenced_assets_encrypted.size > 0
    composition_summary[ :crypto ] = 'KDM required'
    composition_requires_kdm = true
    @encrypted_compositions += 1
  elsif cpl_referenced_assets_encrypted_inferred_from_key_id.size > 0
    composition_summary[ :crypto ] = 'KDM required'
    composition_requires_kdm = true
    @encrypted_compositions += 1
  else
    composition_summary[ :crypto ] = 'Plaintext'
    composition_requires_kdm = false
  end

  # Monoscopic/Stereoscopic composition?
  if is_stereoscopic.uniq.size == 1 and is_stereoscopic.uniq.first == true
    composition_summary[ :spatiality ] = '3D'
    is_stereoscopic = true
  elsif is_stereoscopic.uniq.size == 1 and is_stereoscopic.uniq.first == false
    composition_summary[ :spatiality ] = '2D'
    is_stereoscopic = false
  elsif is_stereoscopic.uniq.size == 2
    composition_summary[ :spatiality ] = '2D/3D'
    is_stereoscopic = true
    errors << "CPL #{ cpl_id }: " + report.last # ? FIXME
    cpl_errors = true
  end

  # Check consistency of decomposition levels in picture essence
  if composition_picture_decomposition_levels.uniq.size == 1 and composition_picture_decomposition_levels.first != nil
    # we're good
  elsif composition_picture_decomposition_levels.uniq.size == 1 and composition_picture_decomposition_levels.first == nil
    errors << "CPL #{ cpl_id }: Failed to read DecompositionLevels from picture essence. Should not happen ❌"
    cpl_errors = true
  else
    unless composition_picture_decomposition_levels.size == 0 # Supplemental/VF/External
      errors << "CPL #{ cpl_id }: Found inconsistent image DecompositionLevels values across the composition (#{ composition_picture_decomposition_levels.each_with_index.map { |v, index| 'Reel ' + ( index + 1 ).to_s + ': ' + v.to_s }.join( ', ' ) }). This will produce visual artefacts in reel transitions ❌"
      cpl_errors = true
    end
  end

  # Set up composition_picture_aspect_ratio
  composition_picture_aspect_ratio = nil
  if composition_picture_aspect_ratios.size == reels.size
    if composition_picture_aspect_ratios.uniq.size == 1
      case composition_picture_aspect_ratios.first
      when 1.896
        composition_picture_aspect_ratio = { :abbrev => 'C', :name => 'Full Container' }
      when 1.85
        composition_picture_aspect_ratio = { :abbrev => 'F', :name => 'Flat' }
      when 2.387
        composition_picture_aspect_ratio = { :abbrev => 'S', :name => 'Scope' }
      when 1.778
        composition_picture_aspect_ratio = { :abbrev => 'HD', :name => 'HD' }
      else
        composition_picture_aspect_ratio = { :abbrev => composition_picture_aspect_ratios.first.to_s, :name => composition_picture_aspect_ratios.first.to_s }
      end
      composition_summary[ :aspect ] = composition_picture_aspect_ratio[ :name ]
    else
      errors << "CPL #{ cpl_id }: Found different asset aspect ratios: #{ composition_picture_aspect_ratios.inspect } ❌"
      cpl_errors = true
    end
  else
    expected_aspect_ratios = reels.size - supplemental_refs[ :main_picture ]
    if expected_aspect_ratios != composition_picture_aspect_ratios.size
      errors << "CPL #{ cpl_id }: Expected to scrounge #{ amount( 'aspect ratio', expected_aspect_ratios ) } (#{ amount( 'reel', reels.size ) }) but got #{ composition_picture_aspect_ratios.size } ❌"
      cpl_errors = true
    end
  end

  # Set up composition_picture_resolution
  composition_picture_resolution = nil
  if composition_picture_resolutions.size == reels.size
    if composition_picture_resolutions.uniq.size == 1
      case composition_picture_resolutions.first
      when '2K'
        case composition_edit_rate
        when 48.0
          composition_picture_resolution = { :abbrev => '48' } # yeah, well. Look it up in 3.9, it's true :) (Changed in 8.2)
        else
          composition_picture_resolution = { :abbrev => '2K' }
        end
      when '4K'
        composition_picture_resolution = { :abbrev => '4K' }
      when 'HD'
        composition_picture_resolution = { :abbrev => 'HD' }
      else
        composition_picture_resolution = { :abbrev => composition_picture_resolutions.first }
      end
      composition_summary[ :resolution ] = composition_picture_resolution[ :abbrev ]
    else
      errors << "CPL #{ cpl_id }: Found different picture resolutions: #{ composition_picture_resolutions.inspect } ❌"
      cpl_errors = true
    end
  else
    expected_picture_resolutions = reels.size - supplemental_refs[ :main_picture ]
    if expected_picture_resolutions != composition_picture_resolutions.size
      errors << "CPL #{ cpl_id }: Expected to scrounge #{ amount( 'picture resolution', expected_picture_resolutions ) } (#{ amount( 'reel', reels.size ) }) but got #{ composition_picture_resolutions.size } ❌"
      cpl_errors = true
    end
  end

  # Composition picture bitrate (weighted mean)
  if composition_picture_bitrates_avg.size > 0
    if ! ( composition_picture_bitrates_avg.map { |e| e.values }.flatten.include? nil )
      composition_picture_bitrate_avg = ( composition_picture_bitrates_avg.map { |w| w[ :duration ] * w[ :picture_bitrate_avg_mbs ] }.inject( 0, :+ ) / composition_picture_bitrates_avg.map { |w| w[ :duration ] }.inject( 0, :+ ) ).round( 2 )
      composition_summary[ :picture_bitrate_avg ] = "Avg #{ composition_picture_bitrate_avg } Mb/s"
    else
      composition_summary[ :picture_bitrate_avg ] = "Avg [NaN Mb/s]"
    end
  else
    composition_summary[ :picture_bitrate_avg ] = "Avg [NaN Mb/s]"
  end

  # Check consistency of channel formats in sound essence
  if composition_sound_channel_formats.uniq.size == 1 and composition_sound_channel_formats.first != nil
    # we're good
  elsif composition_sound_channel_formats.uniq.size == 1 and composition_sound_channel_formats.first == nil
    errors << "CPL #{ cpl_id }: Failed to read sound ChannelFormat values from sound essence. Should not happen"
    cpl_errors = true
  else
    unless composition_sound_channel_formats.size == 0 # Supplemental/VF/External
      errors << "CPL #{ cpl_id }: Found inconsistent sound ChannelFormat values across the composition (#{ composition_sound_channel_formats.each_with_index.map { |v, index| 'Reel ' + ( index + 1 ).to_s + ': ' + v.to_s }.join( ', ' ) }). Playback will fail completely"
      cpl_errors = true
    end
  end

  # Set up composition_sound_channel_count
  composition_sound_channel_count = nil
  if composition_sound_channel_counts.size == reels.size
    if composition_sound_channel_counts.uniq.size == 1
      composition_sound_channel_count = { :abbrev => composition_sound_channel_counts.uniq.first }
    else
      errors << "CPL #{ cpl_id }: Found different sound channel configurations: #{ composition_sound_channel_counts.inspect }"
    end
  else
    expected_audio_types = reels.size - supplemental_refs[ :main_sound ]
    if expected_audio_types != composition_sound_channel_counts.size
      errors << "CPL #{ cpl_id }: Expected to scrounge #{ amount( 'audio type', expected_audio_types ) } (#{ amount( 'reel', reels.size ) }) but got #{ composition_sound_channel_counts.size } ❌"
      cpl_errors = true
    end
  end

  # Check if reels reference both picture and sound. If not report an error for SMPTE CPL and a hint for Interop CPL
  # See SMPTE ST 429-2:2009 section 9.1 for the requirement
  reels_references.each_with_index do |reel_refs, index|
    if reel_refs[ :picture ] and reel_refs[ :sound ] # :picture covers both MainPicture and MainStereoscopicPicture
      cpl_reels_references_complete << true
    else
      reel_no = index + 1
      assets_missing_refs = Array.new
      assets_missing_refs << 'MainPicture or MainStereoscopicPicture' if ! reel_refs[ :picture ]
      assets_missing_refs << 'MainSound' if ! reel_refs[ :sound ]
      reels_report << "#{ composition_type }: Reel #{ reel_no }: Missing #{ amount( 'reference', assets_missing_refs ) } ❌: #{ assets_missing_refs.join( ', ' ) }"
      case composition_type
      when MStr::AssetTypeSmpte
        errors << "CPL #{ cpl_id }: #{ reels_report.last }"
        cpl_errors = true
      else
        hints << "CPL #{ cpl_id }: #{ reels_report.last }"
      end
      cpl_reels_references_complete << false
    end
  end

  # Fire off a hint wrt Interop composition and non-24 fps composition edit rate
  if composition_type == 'Interop' && composition_edit_rate != 24.0
    report << "Interop composition with non-24 fps edit rate (#{ composition_edit_rate })"
    hints << "CPL #{ cpl_id }: Interop composition with non-24 fps edit rate (#{ composition_edit_rate }). Playback may fail on very old legacy systems"
  end

  # composition summary one-liner
  composition_summaries << composition_summary
  report << composition_summary_oneliner( composition_summary )

  # Composition completeness
  if assets_status_list.include?( false )
    if broken_assets.size != 0
      report << "Composition incomplete ❌: Broken assets: #{ broken_assets.inspect }"
      errors << "CPL #{ cpl_id }: Composition incomplete ❌"
      cpl_errors = true
    else
      report << "Composition incomplete: Supplemental/VF/External"
      hints << "CPL #{ cpl_id }: #{ cpl_file }: Composition incomplete: Supplemental/VF/External"
    end
    # FIXME cpl_reels_references_complete.size == reels.size (and thus > 0) only in all-SMPTE CPLs
  elsif cpl_reels_references_complete.include?( false )
    incomplete_reels = Array.new
    cpl_reels_references_complete.each_with_index do |e, i| incomplete_reels << ( i + 1 ).to_s if e == false end
    case composition_type
    when MStr::AssetTypeSmpte
      report << "Composition incomplete ❌: SMPTE reels require both MainPicture or MainStereoscopicPicture and MainSound: #{ plural( 'Reel', incomplete_reels ) } #{ incomplete_reels.join( ', ' ) } incomplete"
      errors << "CPL #{ cpl_id }: #{ report.last }"
      cpl_errors = true
    else
      report << "Composition warning: Reference both MainPicture or MainStereoscopicPicture and MainSound in reels in order to avoid playback issues in the field: See #{ plural( 'reel', incomplete_reels ) } #{ incomplete_reels.join( ', ' ) }"
      hints << "CPL #{ cpl_id }: #{ report.last }"
    end
  else
    report << 'Composition complete ✅'
  end
  if cpl_errors == true
    report << "There were errors ❌. See CPL #{ cpl_id } errors #{ error_output }"
  end

  return composition_summary, report, errors, hints, info
end # cpl_inspect_xml


def find_assetmap_candidates( package_dir )
  begin
    am_candidates, err, status = Open3.capture3( "#{ @fdfind } ASSETMAP '#{ package_dir }'" )
    am_candidates = am_candidates.split( "\n" )
  rescue Exception => e
    @logger.info e.message
    exit FILE_ACCESS_ERROR
  end
  return am_candidates
end


def dcp_inspect( options, arg )
  errors = Array.new
  hints = Array.new
  hints << 'Schema checks were skipped' unless options.validate
  info = Array.new
  composition_summaries = Array.new

  #
  # collect all files dangling below arg
  #
  @package_dir = arg

  #
  # Find files called what Assetmap(s) would be called.
  # Don't assume they're actually Assetmaps before checking.
  #
  am_candidates = find_assetmap_candidates( @package_dir )
  if am_candidates.empty?
    info << 'No Assetmap candidates found'
  else
    @logger.debug "Found #{ amount( 'Assetmap candidate', am_candidates ) } ✅:"
    am_candidates.each do |am_candidate|
      @logger.debug am_candidate
    end
  end

  # Check XML for Assetmap content
  unless am_candidates.empty?
    am_candidates_tmp = am_candidates.dup
    am_candidates.each do |am_candidate|
      am_file = package am_candidate
      error_status = false
      xml, errors, error_status = get_xml_of_type( 'AssetMap', am_file, errors, error_status )
      if xml

        # Schema validation
        am_id = get_asset_uuid( am_file )
        if options.validate
          begin
            valid, errors, error_status = validation( errors, true, xml, am_file, am_id, 'AM' )
            @logger.debug "AM #{ am_id.nil? ? am_id.inspect : am_id }: Schema check: #{ valid ? 'OK ✅' : "Errors ❌ (See #{ error_output })" }: #{ am_file }"
          rescue Exception => e
            errors << "AM #{ am_id.nil? ? am_id.inspect : am_id }: Exception in Schema check ❌: #{ e.message }"
            error_status = true
            @logger.debug errors.last
          end
        end

      else
        @logger.debug "Assetmap candidate: #{ am_file }: Not XML"
        am_candidates_tmp.delete( am_candidate )
      end
    end
    am_candidates = am_candidates_tmp.dup
  end
  am_files = am_candidates
  @logger.debug ''

  # Process all Assetmaps
  @logger.debug "Found #{ amount( 'Assetmap', am_files ) }"
  dict = Array.new # list of dictionaries/hashes
  pkls = Array.new
  pkls_missing = Array.new
  ams = Array.new
  am_files.each_with_index do |am_file, index|
    am_errors = false
    dict << Hash.new
    pkls << Array.new
    pkls_missing << Array.new
    am_base = File.dirname am_file
    xml = xml?( package am_file )
    if xml.root.namespace
      am_ns = xml.root.namespace.href
    end

    # FIXME
    xml.remove_namespaces!
    am_id = get_asset_uuid( package am_file )

    if am_id
      ams << am_id

      case am_ns
      when MStr::Smpte_am
        unless File.basename( am_file ) == 'ASSETMAP.xml'
          errors << "AM #{ am_id }: #{ am_file.inspect }: SMPTE Assetmap file cannot be named #{ File.basename( am_file ).inspect }. Must be named \"ASSETMAP.xml\""
          am_errors = true
        end
      when MStr::Interop_am
        unless File.basename( am_file ) == 'ASSETMAP'
          errors << "AM #{ am_id }: #{ am_file.inspect }: Interop Assetmap file cannot be named #{ File.basename( am_file ).inspect }. Must be named \"ASSETMAP\""
          am_errors = true
        end
      else
        errors << "AM #{ am_id }: #{ am_file.inspect }: Alleged AM file has invalid namespace #{ am_ns.inspect }"
        am_errors = true
      end

      #
      # Good to go minus possible namespace issue
      #
      # collect all asset nodes
      assets = xml.xpath( '//Asset' )

      @logger.debug "AM #{ am_id }: #{ am_file }"
      @logger.debug "AM #{ am_id } lists #{ amount( 'asset', assets.size ) }:"

      # Store asset info in a dictionary (uuid => path, relative to package root)
      # look for PackingList(s)
      assets.each do |asset|

        listed_id = asset.xpath( 'Id' ).text.split( ':' ).last
        # FIXME ChunkList.size == 1 is an assumption and wrong at that. Could be > 1
        # using AM listed path for listing message, not package path, because this is what we're looking at right now:
        path = asset.xpath( 'ChunkList/Chunk/Path' ).text.split( /file:\/+/ ).last

        # Check for UUID specs. Defer RFC-4122 compliance check to a later stage where we know asset kind
        # DCSubtitle does not require RFC-4122 UUID
        if listed_id.downcase !~ MStr::Uuid_re
          errors << "AM #{ am_id }: Listed in Assetmap: Not a UUID: #{ path }: #{ listed_id }"
          am_errors = true
        end

        # Path element present? See e.g. mc t28 ASSETMAP.xml
        if path.nil?
          errors << "AM #{ am_id }: No path for asset: #{ listed_id }"
          am_errors = true
        else

          # Assetmap dictionary
          dict[ index ][ listed_id ] = Pathname( File.join( am_base, path ) ).cleanpath.to_s
          asset_file = package dict[ index ][ listed_id ]
          @logger.debug "#{ listed_id }: #{ dict[ index ][ listed_id ] }#{ File.exist?( package dict[ index ][ listed_id ] ) ? '' : ' (file missing) ❌' }"

          # Check listed_id vs actual asset_id
          if File.exist?( asset_file )
            asset_id = get_asset_uuid( asset_file )
            if asset_id
              unless asset_id.downcase =~ MStr::Uuid_re
                errors << "AM #{ am_id }: Asset UUID: Not a UUID ❌: #{ asset_file }: #{ asset_id }"
                am_errors = true
              end
              if listed_id.downcase != asset_id.downcase
                errors << "AM #{ am_id }: UUID mismatch ❌: #{ asset_file }: Listed: #{ listed_id } Asset: #{ asset_id }"
                am_errors = true
              else
                if listed_id != asset_id
                  hints << "AM #{ am_id }: UUID case mismatch: #{ asset_file }: Listed: #{ listed_id } Asset: #{ asset_id }"
                end
              end
            end
          else
            errors << "AM #{ am_id }: Listed asset file missing ❌: #{ listed_id }: #{ path }: #{ asset_file }"
            am_errors = true
          end

          # Check for Chunklist:Chunk:Length element and compare to actual asset size.
          # In the case of a mismatch this results in a hint as Length is optional
          # and no crucial processing can depend on it. Field behaviour undefined ttbomk.
          if File.exist?( asset_file )
            length_el = asset.xpath( 'ChunkList/Chunk/Length' )
            if ! length_el.empty?
              begin
                listed_asset_length = asset.xpath( 'ChunkList/Chunk/Length' ).text.to_i
                asset_size = File.size asset_file
                unless listed_asset_length == asset_size
                errors << "AM #{ am_id }: Mismatch in optional Length element ❌: Asset: #{ listed_id }: Listed length: #{ listed_asset_length } (#{ listed_asset_length.to_k }) #{ asset_file.inspect } on medium: #{ asset_size } (#{ asset_size.to_k })"
                  am_errors = true
                end
              rescue Exception => e
                errors << "AM #{ am_id }: Asset #{ listed_id }: File #{ asset_file.inspect }: Length check fail ❌: #{ e.message }"
                am_errors = true
              end
            end
          end

          # Check asset filename for whitespace (keep this as distinct check)
          if path.scan( /\s+/ ).size != 0
            case am_ns
            when MStr::Smpte_am
              errors << "AM SMPTE #{ am_id }: Asset #{ listed_id }: Filename #{ path.inspect } contains whitespace"
              am_errors = true
            when MStr::Interop_am
              hints << "AM Interop #{ am_id }: Asset #{ listed_id }: Filename #{ path.inspect } contains whitespace. Avoid whitespace in filenames"
            end
          end
          # Check asset filename for codepoints outside of [0-9A-Za-z_-.]
          char_outsiders = /[^-._0-9A-Za-z]/
          match_char_outsiders = path.split('').map { |m| m =~ char_outsiders }
          if match_char_outsiders.include? 0
            path_hinted = ''
            path.split('').each_with_index do |m, i|
              if match_char_outsiders[i].nil?
                path_hinted += m
              else
                path_hinted += m.invert
              end
            end
            case am_ns
            when MStr::Smpte_am
              errors << "AM SMPTE #{ am_id }: Asset #{ listed_id }: Filename \"#{ path_hinted }\" contains characters outside of (-._0-9A-Za-z)"
              am_errors = true
            when MStr::Interop_am
              hints << "AM Interop #{ am_id }: Asset #{ listed_id }: Filename \"#{ path_hinted }\" contains characters outside of (-._0-9A-Za-z). Avoid these characters in filenames"
            end
          end
          # Check asset filename for length
          if am_ns == MStr::Smpte_am and path.codepoints.size > 100
            errors << "AM SMPTE #{ am_id }: Asset #{ listed_id }: Filename #{ path.inspect } longer than 100 characters: #{ path.codepoints.size } characters"
            am_errors = true
          end
          if am_ns == MStr::Interop_am and path.codepoints.size > 255
            errors << "AM Interop #{ am_id }: Asset #{ listed_id }: Filename #{ path.inspect } longer than 255 characters: #{ path.codepoints.size } characters"
            am_errors = true
          end

        end # path.nil?

        # PackingList?
        unless asset.xpath( 'PackingList' ).empty?
          if path
            case am_ns
            when MStr::Interop_am
              pkls[ index ] << listed_id
            when MStr::Smpte_am
              if asset.xpath( 'PackingList' ).text == 'true'
                pkls[ index ] << listed_id
              else
                errors << "AM #{ am_id }: SMPTE AM requires a PackingList element to contain the value 'true' (value is missing). Continuing anyway"
                am_errors = true
                pkls[ index ] << listed_id
              end
            end
          else
            errors << "AM #{ am_id }: Found alleged PackingList asset #{ listed_id } but Path element is empty. Not adding to dictionary ❌"
            am_errors = true
          end
        end

        # Check if possible uuid component in the asset filename matches the actual asset uuid
        if dict[ index ][ listed_id ]
          file_basename = File.basename( dict[ index ][ listed_id ] )
          if file_basename =~ MStr::Uuid_particle_re
            unless file_basename.match( MStr::Uuid_particle_re )[ 0 ] == listed_id
              hints << "Asset UUID and filename UUID component mismatch: #{ listed_id } -> #{ file_basename }"
            end
          end
        end

      end # assets.each

    else
      ams << nil
      errors << "Assetmap '#{ am_file }' has no Id"
      am_errors = true
    end

    # List this Assetmap's PKLs
    @logger.debug "Assetmap #{ am_id } lists #{ amount( 'PKL', pkls[ index ] ) }:"
    pkls[ index ].map { |pkl_id|
      pkl_file = package dict[ index ][ pkl_id ]
      if File.exist?( pkl_file )
        @logger.debug "PKL file present ✅: #{ pkl_id }: #{ pkl_file }"
      else
        pkls_missing[ index ] << pkl_id
        errors << "AM #{ am_id }: PKL file missing ❌: #{ pkl_id }: #{ pkl_file }"
        am_errors = true
        @logger.debug errors.last
      end
    }
    pkls_missing[ index ].map { |pkl_id| pkls[ index ].delete pkl_id }

    if am_errors == true
      @logger.debug "There were errors ❌. See AM #{ am_id } errors #{ error_output }"
    end

    @logger.debug nil

  end # am_files.each

  #
  # Experimental option --as-asset-store
  #
  # This will merge all collected dictionaries and flatten pkls accordingly.
  # Naive merge, though, for now. No asset normalization either.
  #
  # Also composition completeness info won't hint at the "use"
  # of external assets. Use if you know what you are doing.
  #
  # Can be used to simulate ingest and completeness checks for VF compositions.
  #
  if options.as_asset_store
    dict_tmp = Array.new << Hash.new
    # dict.map { |d| dict_tmp.first.merge!( d ) { |k, v1, v2| hints << "Experimental option --as-asset-store: Duplicate key: #{ k } => #{ v1 == v2 ? 'v1 == v2' : "\n\t\tv1: #{ v1 || 'nil' }\n\t\tv2: #{ v2 || 'nil' }" }"; v1 || v2 } }
    dict.map { |d| dict_tmp.first.merge!( d ) { |k, v1, v2| v1 || v2 } }
    dict = dict_tmp 
    pkls = Array.new << pkls.flatten
  end

  # List all found PKLs
  @logger.debug "Found #{ amount( 'Package', pkls.flatten ) }"
  pkls.each_with_index do |am_pkls, index|
    am_pkls.each do |pkl_id|
      if dict[ index ][ pkl_id ]
        pkl_file = package dict[ index ][ pkl_id ]
        #@logger.debug "PKL file#{ File.exist?( pkl_file ) ? '' : ' not' } present:"
        if File.exist?( pkl_file )
          @logger.debug "PKL file present ✅: #{ [ pkl_id, pkl_file ].join( ': ' ) }"
        else
          @logger.debug "PKL file missing ❌: #{ [ pkl_id, pkl_file ].join( ': ' ) }"
        end
      end
    end
  end
  @logger.debug ''

  # Process all PackingLists
  cpls = Array.new
  cpls_missing = Array.new
  packages_size_listed = 0
  packages_size_actual = 0

  pkls.each_with_index do |am_pkls, index|
    cpls << Array.new
    cpls_missing << Array.new
    am_pkls.each do |pkl_id|
      pkl_errors = false
      pkl_file = package dict[ index ][ pkl_id ]
      xml, errors, pkl_errors = get_xml_of_type( 'PackingList', pkl_file, errors, pkl_errors )
      if xml

        @logger.debug "PKL #{ pkl_id }: #{ pkl_file }"

        if options.validate
          begin
            valid, errors, pkl_errors = validation( errors, pkl_errors, xml, pkl_file, pkl_id, 'PKL' )
            @logger.debug "PKL #{ pkl_id }: Schema check: #{ valid ? 'OK ✅' : "Errors ❌ (See #{ error_output })" }"
          rescue Exception => e
            errors << "PKL #{ pkl_id }: Exception in Schema check ❌: #{ e.message }"
            pkl_errors = true
            @logger.debug errors.last
          end
        end

        if @c14n_available
          signature_result = check_signature( xml )
          if signature_result.verified? and signature_result.crypto.errors[ :context ].values.flatten.empty?
            @signed_pkls_verified_count += 1
          end
          errors, pkl_errors = errors_signature_verification( errors, pkl_errors, signature_result, pkl_id, pkl_file, 'PKL' )
          @logger.debug "PKL #{ pkl_id }: #{ signature_result.messages.last }"
          if signature_result and ! signature_result.signature_node.empty?
            @signed_pkls_count += 1
            sig_info = signer_info( xml, signature_result )
            @logger.debug "Signer:        #{ sig_info[ :signer_name ] }" if sig_info[ :signer_name ]
            @logger.debug "Signer issuer: #{ sig_info[ :signer_issuer_name ] }" if sig_info[ :signer_issuer_name ]

            # Todo: Compare names in Signer and certificate
            #

            # Check Signer.X509Data.X509IssuerSerial info vs signer certificate
            # See e.g. dcp_2/V174* for a serial mismatch
            if ! signature_result.signer_node.empty? and sig_info[ :x509serialnumber ] and sig_info[ :cert_serial ]
              if sig_info[ :x509serialnumber ] != sig_info[ :cert_serial ]
                errors << "PKL #{ pkl_id }: Signer serial mismatch ❌: X509SerialNumber: #{ sig_info[ :x509serialnumber ] } Certificate: #{ sig_info[ :cert_serial ] }"
                pkl_errors = true
                @logger.debug errors.last
              end
            else
              errors << "PKL #{ pkl_id }: Signer info :x509serialnumber or :cert_serial could not be retrieved"
              pkl_errors = true
              @logger.debug errors.last
            end
          end
        else
          signature_result = nil
        end

        # FIXME
        xml.remove_namespaces!

        pkl_annotation_text = xml.xpath( '/PackingList/AnnotationText' ).text
        if pkl_annotation_text.empty?
          @logger.debug "PKL #{ pkl_id }: AnnotationText: [Empty]"
        else
          @logger.debug "PKL #{ pkl_id }: AnnotationText: #{ pkl_annotation_text }"
        end

        package_size_listed = 0
        package_size_actual = 0
        pkl_cpls = Array.new

        pkl_assets = xml.xpath( '//Asset' )
        @logger.debug "PKL #{ pkl_id } lists #{ amount( 'asset', pkl_assets.size ) }"

        pkl_assets.each do |asset|
          id = asset.xpath( 'Id' ).text.split( ':' ).last
          if id.empty?
            errors << "PKL #{ pkl_id }: Asset Id missing ❌"
            pkl_errors = true
          end
          type = asset.xpath( 'Type' ).text
          if type.empty?
            errors << "PKL #{ pkl_id }: Asset type not specified: #{ id }"
            pkl_errors = true
          end
          # List all assets listed in PKL and report AM mapping status
          @logger.debug "#{ id }: #{ type.empty? ? '[Type not specified in PKL]' : type }: #{ dict[ index ][ id ] ? File.exist?( package dict[ index ][ id ] ) ? dict[ index ][ id ] : dict[ index ][ id ] + ' (missing) ❌' : 'Asset UUID not in assetmap dictionary' }"

          if dict[ index ].keys.include?( id )
            asset_file = package dict[ index ][ id ]
            size_listed = asset.xpath( 'Size' ).text.to_i

            if File.exist?( asset_file )
              size_asset = File.size( asset_file )
              #
              # Plug in checks here. we might be skipping validation hence the tag test
              #
              # Check listed and actual asset size
              if size_listed
                if size_listed != size_asset
                  errors << "PKL #{ pkl_id }: Size mismatch ❌: #{ id }: PKL: #{ size_listed } (#{ size_listed.to_k }) Asset: #{ size_asset } (#{ size_asset.to_k })"
                  pkl_errors = true
                end
                package_size_listed += size_listed
                package_size_actual += size_asset
              else
                errors << "PKL #{ pkl_id }: Size tag missing or bad content ❌: #{ id }: #{ asset_file }: #{ type.empty? ? '[Type not specified in PKL]' : type }"
                pkl_errors = true
              end

              # Check listed and actual digests
              if ! asset.xpath( 'Hash' ).empty?
                if ( hash_listed = asset.xpath( 'Hash' ).text )
                  if hash_listed.empty?
                    errors << "PKL #{ pkl_id }: Hash element is empty: See PKL file #{ pkl_file } line #{ asset.xpath( 'Hash' ).first.line }"
                    errors << "PKL #{ pkl_id }: Asset has no associated hash value in metadata: #{ id }: #{ asset_file }: #{ type.empty? ? '[Type not specified in PKL]' : type }"
                    @logger.debug "#{ id }: Checking hash value: Asset has no associated hash value in metadata: See errors #{ error_output }"
                    pkl_errors = true
                  else
                    if options.check_hashes
                      if options.check_hashes_limit == :no_limit or bytes_from_nice_bytes( options.check_hashes_limit ) > size_asset
                        @check_hashes_hits += 1
                        etabar_title = "#{ id }: Checking hash value:"
                        hash_check, eta = digest_with_etabar( digest_algorithm = 'sha1', title = etabar_title, file = asset_file, width = 20, looks_like = '[= ]', opts = options, logger = @logger )
                        hash_check = Base64.encode64( hash_check ).chomp
                        if hash_listed != hash_check
                          eta.preserve_terminal_title_with_message( "Mismatch ❌ (#{ time_string( eta.elapsed ) })" )
                          errors << "PKL #{ pkl_id }: Hash mismatch ❌: #{ id }: PKL: #{ hash_listed } Asset: #{ hash_check }"
                          pkl_errors = true
                        else
                          eta.preserve_terminal_title_with_message( "OK ✅ (#{ time_string( eta.elapsed ) })" )
                          # info << "Hash value: OK: #{ id }: #{ asset_file }: #{ hash_check }"
                        end
                      else
                        @check_hashes_limit_hits += 1
                        @logger.debug "#{ id }: Hash check skipped: File size #{ size_asset.to_k } > #{ bytes_from_nice_bytes( options.check_hashes_limit ).to_k } limit: Path: #{ asset_file }, Expected hash: #{ hash_listed }"
                        hints << "PKL #{ pkl_id }: Hash check skipped: File size #{ size_asset.to_k } > #{ bytes_from_nice_bytes( options.check_hashes_limit ).to_k } limit: Asset #{ id }, Path #{ asset_file }, Expected hash: #{ hash_listed }"
                      end
                    else
                      @logger.debug "#{ id }: Hash check skipped: Path: #{ asset_file }, Expected hash: #{ hash_listed }"
                    end
                  end
                end
              else
                errors << "PKL #{ pkl_id }: Hash element missing or bad content ❌: #{ asset_file }: #{ type.empty? ? '[Type not specified in PKL]' : type }: #{ id }"
                pkl_errors = true
              end

              # Pick CPLs
              if type =~ /text\/xml/
                xml, errors, errors_status = get_xml_of_type( 'CompositionPlaylist', asset_file, errors, errors_status = false )
                if xml
                  pkl_cpls << id
                  cpls[ index ] << id
                end
              end
              #
              #
            else
              # asset_file does not exist
              errors << "PKL #{ pkl_id }: Asset file missing ❌: #{ id }: #{ asset_file }"
              pkl_errors = true
              package_size_listed += size_listed
              package_size_actual += 0
            end

          else
            # For some reason the listed id in PackingList is not in assetmap dictionary
            # Possibly been tampered with
            errors << "Asset UUID not in assetmap dictionary: PKL #{ pkl_id }: #{ id } (#{ type })"
            pkl_errors = true
          end

        end
        @logger.debug "PKL #{ pkl_id }: Package size: #{ package_size_actual == package_size_listed ? package_size_actual.to_k : package_size_actual.to_k + ' (Listed: ' + package_size_listed.to_k + ')' }"
        # List this PKLs CPLs
        @logger.debug "PKL #{ pkl_id } lists #{ amount( 'composition', pkl_cpls ) }"
        pkl_cpls.map { |cpl_id|
          cpl_file = package dict[ index ][ cpl_id ]
          if File.exist?( cpl_file )
            @logger.debug "CPL file present ✅: #{ cpl_id }: #{ cpl_file }"
          else
            cpls_missing[ index ] << cpl_id
            errors << "CPL #{ cpl_id }: CPL file missing ❌: #{ cpl_file }"
            @logger.debug errors.last
            pkl_errors = true
          end
        }
        cpls_missing[ index ].map { |cpl_id| cpls[ index ].delete cpl_id }
      else
        errors << "Not a PackingList: #{ pkl_file }"
        @logger.debug errors.last
        pkl_errors = true
      end
      if package_size_listed
        packages_size_listed += package_size_listed
        packages_size_actual += package_size_actual
        package_size_listed, package_size_actual = nil, nil
      end

      if pkl_errors == true
        @logger.debug "There were errors ❌. See PKL #{ pkl_id } errors #{ error_output }"
      end

      @logger.debug ''
    end # am_pkls.each
  end # pkls.each

  # List all found CPLs
  if cpls.flatten.size > 0
    @logger.debug "Found #{ amount( 'Composition', cpls.flatten ) }"
    dict.each_with_index do |dictionary, index|
      cpls[ index ].each do |cpl_id|
        cpl_file = package dictionary[ cpl_id ]
        if File.exist? cpl_file
          @logger.debug "CPL file present ✅: #{ cpl_id }: #{ cpl_file }"
        else
          errors << "CPL #{ cpl_id }: CPL file missing ❌: #{ cpl_file }"
          @logger.debug errors.last
        end
      end
    end
  else
    @logger.info 'Found no compositions'
  end
  @logger.debug ''

  # Inspect CPLs
  # FIXME and all over again ...
  audio_stats = Hash.new
  dict.each_with_index do |dictionary, index|
    cpls[ index ].each do |cpl_id|
      if dictionary.include?( cpl_id )
        cpl_file = package dictionary[ cpl_id ]
        if File.exist?( cpl_file )
          xml = xml?( cpl_file )
          if xml

            composition_summary, report, errors, hints, info = cpl_inspect_xml( xml, dictionary, audio_stats, @package_dir, composition_summaries, errors, hints, info, options )
          else
            errors << "PKL listed CPL is not XML ❌: #{ cpl_file }: #{ cpl_id }"
          end
        else
          report << "CPL file missing ❌: #{ cpl_file }"
        end
        report.map { |line| @logger.cpl line }
        @logger.cpl ''
      end
    end
  end


  # prep for Info summary block
  pkls = pkls.flatten
  cpls = cpls.flatten
  execution_time_seconds = Time.now - AppStartSeconds
  execution_time = Timecode.new( execution_time_seconds.round, 60 ).to_s
  total_size = "#{ packages_size_actual == packages_size_listed ? packages_size_actual.to_k : packages_size_actual.to_k + ' (Listed total: ' + packages_size_listed.to_k + ')' }"
  pkls_signature_info = "#{ @signed_pkls_count } signed#{ @signed_pkls_count > 0 ? '/' + @signed_pkls_verified_count.to_s + ' verified' : '' }"
  cpls_signature_info = "#{ @signed_cpls_count } signed#{ @signed_cpls_count > 0 ? '/' + @signed_cpls_verified_count.to_s + ' verified' : '' }"
  cpls_encryption_info = "#{ cpls.size - @encrypted_compositions > 0 ? ( cpls.size - @encrypted_compositions ).to_s + ' plaintext/' : '' }#{ amount( 'KDM', @encrypted_compositions ) } required)"

  # Info summary block
  composition_summaries.each do |composition_summary|
    info << composition_summary_oneliner( composition_summary )
  end
  info << "#{ AppName } #{ AppVersion } (asdcplib #{ ASDCPVersion }, #{ RubyVersionPlatform }) on #{ RunDatetime_friendly } (#{ execution_time })"
  info << "Inspected: #{ Pathname( arg ).realpath }"
  info << "Found #{ amount( 'Package', pkls ) } with total size #{ total_size }"
  info << 'Hash checks skipped' if options.check_hashes == false
  info << "Hash checks skipped for assets bigger than #{ @check_hashes_limit_nice }" if @check_hashes_limit_nice
  info << "Hash checks skipped for #{ amount( 'asset', @check_hashes_limit_hits ) } of #{ @check_hashes_hits + @check_hashes_limit_hits } total" if @check_hashes_limit_nice
  info << 'Schema checks skipped' unless options.validate
  info << 'Audio analysis skipped' unless options.audio_analysis
  info << "Found #{ amount( 'Assetmap', am_files ) }, #{ amount( 'Package', pkls ) } (#{ pkls_signature_info }), #{ amount( 'Composition', cpls ) } (#{ cpls_signature_info }, #{ cpls_encryption_info }"
  info << "#{ amount( 'Error', errors ) }#{ errors.size == 0 ? ' ✅' : ' ❌' }, #{ amount( 'Hint', hints ) }"

  return { :errors => errors, :hints => hints, :info => info, :am_files => am_files, :pkls => pkls, :cpls => cpls, :pkls_missing => pkls_missing, :cpls_missing => cpls_missing }
end # dcp_inspect


def print_internal_error_backtrace( result )
  @logger.info "#{ result.class }: #{ result.message }"
  result.backtrace[ 0 .. 4 ].each do |tracer|
    @logger.info tracer
  end
end


def dcp_inspect_crashed_get_in_touch
  @logger.info ''
  @logger.info "Sorry, #{ AppName } #{ AppVersion } crashed"
  @logger.info "Please get in touch to help fix it"
  @logger.info "See https://github.com/wolfgangw"
  @logger.info "Your feedback is much appreciated. Thanks in advance"
  @logger.info ''
end


def graceful_shutdown( options, args, crash = false )
  if @dcp_inspect_temp
    @dcp_inspect_temp.remove
  end
  write_logfiles( options, args )
  if crash
    dcp_inspect_crashed_get_in_touch
  end
end


def write_logfiles( options, args )
  # Write autolog
  if options.logfile_autolog
    autologfile = File.join( ENV[ 'DCP_INSPECT_DIR' ], [ Pathname( args[ 0 ] ).realpath.to_s.gsub( '/', '___' ).gsub( /\s/, '_' ), RunDatetime.to_s.gsub( /\D/, '-' ), AppVersion.split( '.' ).join, rand( 65536 ).to_s( 16 ) ].join( '_' ) + ".#{ AppName }" )
    begin
      File.write( autologfile, @logger.full_log_blob )
      @logger.info "See autolog at #{ autologfile }"
    rescue Exception => e
      @logger.info e.message
      exit AUTOLOGFILE_WRITE_ERROR
    end
  end

  # Write logfile
  if options.logfile
    begin
      File.write( options.logfile, @logger.full_log_blob )
      @logger.info "See logfile at #{ options.logfile }"
    rescue Exception => e
      @logger.info e.message
      exit LOGFILE_WRITE_ERROR
    end
  end
  if options.logfile_append
    begin
      File.open( options.logfile_append, 'a' ) { |logfile| logfile.write @logger.full_log_blob }
      @logger.info "See additions to logfile at #{ options.logfile_append }"
    rescue Exception => e
      @logger.info e.message
      exit LOGFILE_WRITE_ERROR
    end
  end
end

#
# Prepare for main
#

begin

  options = Options.parse( ARGV )
  args = ARGV
  if ENV[ 'DCP_INSPECT_AUTOLOG' ]
    options.logfile_autolog = true
  end
  @logger = DLogger.new( prefix = '', options )


  # Check ruby version. Versions < 1.9.3 not supported
  if RUBY_VERSION < '1.9.3'
    @logger.info "The installed ruby version #{ RUBY_VERSION } (released #{ RUBY_RELEASE_DATE }) is not supported"
    @logger.info "Please install a ruby version >= 1.9.3"
    exit RUBY_VERSION_NOT_SUPPORTED
  end


  # Check required tools
  required_command_not_found = false
  if RubyVersionPlatform =~ /linux/
    @fdfind = 'fdfind'
  elsif RubyVersionPlatform =~ /darwin/
    @fdfind = 'fd'
  end
  required_commands = [ 'asdcp-info', 'asdcp-unwrap', 'kmuuidgen', @fdfind ]
  required_commands << 'sox' if options.audio_analysis
  required_commands.flatten.each do |command|
    if ! command_exists? command
      @logger.info "Required command #{ command } not found. Please run digital-cinema-tools-setup or install the missing component manually"
      required_command_not_found = true
    end
  end
  if required_command_not_found
    exit REQUIRED_COMMAND_NOT_FOUND
  end


  # asdcplib version
  ASDCPVersion = MxfTools.asdcplib_version.join '.'


  # Hello
  @logger.debug "#{ AppName } #{ AppVersion } (asdcplib #{ ASDCPVersion }, #{ RubyVersionPlatform })"


  # Check Nokogiri C14N support
  # Nokogiri git master (2012.01.11) implements interface to libxml2's C14N
  if Nokogiri::XML::Document.new.respond_to?( 'canonicalize' )
    @c14n_available = true
  else
    @c14n_available = false
    @logger.info 'Signature verification: Installed version of Nokogiri does not support C14N. Signature verification will be skipped'
    @logger.info 'Signature verification: Signature verification is a crucial component of full DCP validation'
    @logger.info 'Signature verification: Please consider upgrading your Nokogiri installation'
    @logger.info "Nokogiri: Installed version: #{ Nokogiri::VERSION_INFO }"
  end


  # Check --hash-limit argument
  @check_hashes_hits = 0
  @check_hashes_limit_hits = 0
  unless options.check_hashes_limit == :no_limit
    if options.check_hashes_limit =~ /\d+(\.?\d+)?\s?(kb|mb|gb)?/
      @check_hashes_limit_nice = bytes_from_nice_bytes( options.check_hashes_limit ).to_k
      @logger.info "Will skip hash checks for files bigger than #{ @check_hashes_limit_nice }"
    else
      @check_hashes_limit_nice = nil
      @logger.info "Option --hash-limit argument #{ options.check_hashes_limit.inspect } does not compute.\nUse integer or decimal plus an optional KB, MB or GB symbol, e.g. 700KB or 1.5GB"
      exit BAD_HASH_LIMIT_ARG
    end
  end


  # Set up local XML Catalog and patch its xml:base
  AppDir = File.dirname( Pathname.new( __FILE__ ).realpath )
  XSDDir = File.join( AppDir, 'xsd' )
  local_xml_catalog = File.join( XSDDir, 'catalog.xml' )
  if File.exist?( XSDDir ) and File.ftype( XSDDir ) == 'directory'
    if File.exist? local_xml_catalog
      c = File.read local_xml_catalog
      m = c.match( /xml:base="file:\/\/(.+)">/ )
      if m[ 1 ] != File.join( XSDDir, '' )
        File.write( local_xml_catalog, c.gsub( m[ 1 ], File.join( XSDDir, '' ) ) )
      end
    else
      @logger.info "Local XML Catalog #{ local_xml_catalog } not found"
      exit XML_CATALOG_NOT_FOUND
    end
  else
    @logger.info "Local XSD store #{ XSDDir } not found"
    exit XSD_STORE_NOT_FOUND
  end
  ENV[ 'XML_CATALOG_FILES' ] = local_xml_catalog


  # main
  if args.size == 1 and File.exist?( args[ 0 ] ) and File.directory?( Pathname( args[ 0 ] ).realpath )

    # Full audio/image examination?
    if options.audio_analysis or options.image_analysis
      @dcp_inspect_temp = Pipe.new
      @logger.debug "Image/audio analysis: Setting up temp location at #{ @dcp_inspect_temp.path }"
      @logger.debug 'Image analysis not implemented yet' if options.image_analysis
    end

    # autolog?
    if options.logfile_autolog
      if ENV[ 'DCP_INSPECT_DIR' ]
        if ! confirm_or_create( ENV[ 'DCP_INSPECT_DIR' ] )
          @logger.info "Cannot write to #{ ENV[ 'DCP_INSPECT_DIR' ].inspect }"
          exit DCP_INSPECT_DIR_NOT_WRITABLE
        else
          @logger.info "Will write autolog to #{ ENV[ 'DCP_INSPECT_DIR' ] }"
        end
      else
        @logger.info "Autolog requested but env DCP_INSPECT_DIR is not set"
        @logger.info "Will not write autolog"
        exit ENV_DCP_INSPECT_DIR_NOT_SET
      end
    end

    # Check requested logfile early (exists? overwrite? writable?)
    if options.logfile
      if File.exist?( options.logfile )
        puts " Requested logfile #{ options.logfile.inspect } exists. Will #{ options.overwrite_logfile ? '' : 'not ' }overwrite"
        exit LOGFILE_EXISTS_ERROR unless options.overwrite_logfile
      else
        @logger.info "Will write logfile to #{ options.logfile }"
      end
      if ! confirm_or_create( File.dirname options.logfile )
        puts " Cannot write requested logfile at #{ options.logfile.inspect }. Please specify another location"
        exit LOGFILE_WRITE_ERROR
      end
    end
    if options.logfile_append
      if ! confirm_or_create( File.dirname options.logfile_append )
        puts " Cannot append to requested logfile at #{ options.logfile_append }. Please specify another location"
        exit LOGFILE_WRITE_ERROR
      end
    end

    # Searching at
    @logger.info "Searching Assetmaps at #{ args[ 0 ] }"

    # Inspection
    inspection = dcp_inspect( options, args[ 0 ] )
    print_inspection_messages( inspection ) unless @logger.is_quiet

    # Remove @dcp_inspect_temp
    if options.audio_analysis or options.image_analysis
      if @dcp_inspect_temp
        @dcp_inspect_temp.remove
      end
    end

    # Write requested logfiles
    write_logfiles( options, args )

    case inspection[ :errors ].size
    when 0
      exit DCP_OK
    else
      exit DCP_ERROR
    end

  elsif args.size == 0
    @logger.info "No volume or directory given. See #{ AppName } --help"
    exit NO_ARG
  elsif args.size > 1
    @logger.info "Too many arguments: #{ args.inspect }"
    @logger.info "#{ AppName } wants 1 path/argument. See #{ AppName } --help"
    exit TOO_MANY_ARGS
  else
    @logger.info "Not a volume or directory. See #{ AppName } --help"
    exit ARG_NOT_A_DIR
  end

# Graceful shutdown
rescue Interrupt => signal
  puts
  @logger.info "Shutdown: #{ signal.inspect }"
  graceful_shutdown( options, args )
  exit USER_INTERRUPT
rescue TypeError => error
  print_internal_error_backtrace( error )
  graceful_shutdown( options, args, crash = true )
  exit RUBY_TYPE_ERROR
rescue NameError => error
  print_internal_error_backtrace( error )
  graceful_shutdown( options, args, crash = true )
  exit RUBY_NAME_ERROR
rescue ArgumentError => error
  print_internal_error_backtrace( error )
  graceful_shutdown( options, args, crash = true )
  exit RUBY_ARGUMENT_ERROR
end