Commit 06d9b3d1 authored by Rick Gruber-Riemer's avatar Rick Gruber-Riemer

Solution to issue # 53: enabled writing logging output to files. At the same...

Solution to issue # 53: enabled writing logging output to files. At the same time removed all logging residuals from parameters.py and discarded VERBOSE log level.
parent b60025bd
import argparse
import datetime
from enum import IntEnum, unique
import logging
import logging.config
import multiprocessing as mp
import os
import parameters
......@@ -21,7 +21,7 @@ import utils.aptdat_io as aptdat_io
import utils.calc_tile as calc_tile
import utils.coordinates as coordinates
import utils.stg_io2
from utils.utilities import BoundaryError, FGElev, parse_boundary
from utils.utilities import BoundaryError, FGElev, date_time_now, parse_boundary
class SceneryTile(object):
......@@ -61,12 +61,54 @@ def _parse_exec_for_procedure(exec_argument: str) -> Procedures:
return Procedures.__members__[exec_argument.lower()]
def process_scenery_tile(scenery_tile: SceneryTile, params_file_name: str, log_level: str,
def configure_logging(log_level: str, log_to_file: bool) -> None:
"""Set the logging level and maybe write to file.
See also accepted answer to https://stackoverflow.com/questions/29015958/how-can-i-prevent-the-inheritance-of-python-loggers-and-handlers-during-multipro?noredirect=1&lq=1.
And: https://docs.python.org/3.5/howto/logging-cookbook.html#logging-to-a-single-file-from-multiple-processes
"""
logging_config = {
'formatters': {
'f': {
'format': '%(processName)-10s %(name)s'
' %(levelname)-8s %(message)s',
},
},
'version': 1,
}
handlers_dict = {
'console': {
'level': log_level,
'formatter': 'f',
'class': 'logging.StreamHandler',
}
}
logging_config['handlers'] = handlers_dict
handlers_array = ['console']
if log_to_file:
file_handle_dict = {'level': log_level, 'formatter': 'f', 'class': 'logging.FileHandler'}
process_name = mp.current_process().name
if process_name == 'MainProcess':
file_handle_dict['filename'] = 'osm2city_main_{}.log'.format(date_time_now())
else:
file_handle_dict['filename'] = 'osm2city_process_{}_{}.log'.format(process_name, date_time_now())
handlers_dict['file'] = file_handle_dict
handlers_array.append('file')
logging_config['loggers'] = {'': {'handlers': handlers_array, 'level': log_level, 'propagate': True}}
logging.config.dictConfig(logging_config)
def pool_initializer(log_level: str, log_to_file: bool):
configure_logging(log_level, log_to_file)
def process_scenery_tile(scenery_tile: SceneryTile, params_file_name: str,
exec_argument: Procedures, my_airports: List[aptdat_io.Airport],
file_lock: mp.Lock) -> None:
try:
parameters.read_from_file(params_file_name)
parameters.set_loglevel(log_level)
# adapt boundary
parameters.set_boundary(scenery_tile.boundary_west, scenery_tile.boundary_south,
scenery_tile.boundary_east, scenery_tile.boundary_north)
......@@ -112,11 +154,9 @@ def process_scenery_tile(scenery_tile: SceneryTile, params_file_name: str, log_l
scenery_tile.boundary_east, scenery_tile.boundary_north)
logging.exception(msg)
time_now = datetime.datetime.now().strftime('%Y%m%d_%H:%M:%S - ')
with open("osm2city-exceptions.log", "a") as f:
# print info
f.write(msg + ' at ' + time_now + os.linesep)
f.write(msg + ' at ' + date_time_now() + ' - ' + os.linesep)
# print exception
exc_type, exc_value, exc_traceback = sys.exc_info()
f.write(''.join(traceback.format_exception(exc_type, exc_value, exc_traceback)))
......@@ -125,7 +165,6 @@ def process_scenery_tile(scenery_tile: SceneryTile, params_file_name: str, log_l
if __name__ == '__main__':
logging.basicConfig(level=logging.INFO)
parser = argparse.ArgumentParser(description="build-tiles DB generates a whole scenery of osm2city objects \
based on a lon/lat defined area")
parser.add_argument("-f", "--file", dest="filename",
......@@ -136,19 +175,29 @@ if __name__ == '__main__':
parser.add_argument("-p", "--processes", dest="processes", type=int,
help="number of parallel processes (should not be more than number of cores/CPUs)",
required=True)
parser.add_argument('-m', '--maxtasksperchild', dest='max_tasks', type=int,
help='the number of tasks a worker process completes before it will exit (default: unlimited)',
required=False)
parser.add_argument("-e", "--execute", dest="exec",
help="execute only the given procedure[s] (buildings, pylons, roads, details, main)",
required=False)
parser.add_argument("-l", "--loglevel", dest="loglevel",
help="set loglevel. Valid levels are VERBOSE, DEBUG, INFO, WARNING, ERROR, CRITICAL",
parser.add_argument("-l", "--loglevel", dest="logging_level",
help="set loggging level. Valid levels are DEBUG, INFO (default), WARNING, ERROR, CRITICAL",
required=False)
parser.add_argument('-o', '--logtofile', dest='log_to_file', action='store_true',
help='write the logging output to files in addition to stderr')
args = parser.parse_args()
# configure logging
my_log_level = 'INFO'
if args.logging_level:
my_log_level = args.logging_level.upper()
configure_logging(my_log_level, args.log_to_file)
parameters.read_from_file(args.filename)
if parameters.FLAG_2017_2:
logging.info('Processing for 2017.2 version')
parameters.set_loglevel(args.loglevel) # -- must go after reading params file
exec_procedure = Procedures.all
if args.exec:
......@@ -217,10 +266,15 @@ if __name__ == '__main__':
start_time = time.time()
mp.set_start_method('spawn') # use safe approach to make sure e.g. parameters module is initialized separately
pool = mp.Pool(processes=args.processes, maxtasksperchild=1)
# max tasks per child: see https://docs.python.org/3.5/library/multiprocessing.html#module-multiprocessing.pool
max_tasks_per_child = None # the default, meaning a worker processes will live as long as the pool
if args.max_tasks:
max_tasks_per_child = args.max_tasks
pool = mp.Pool(processes=args.processes, maxtasksperchild=max_tasks_per_child,
initializer=pool_initializer, initargs=(my_log_level, args.log_to_file))
the_file_lock = mp.Manager().Lock()
for my_scenery_tile in scenery_tiles_list:
pool.apply_async(process_scenery_tile, (my_scenery_tile, args.filename, args.loglevel,
pool.apply_async(process_scenery_tile, (my_scenery_tile, args.filename,
exec_procedure, airports, the_file_lock))
pool.close()
pool.join()
......
......@@ -1040,7 +1040,7 @@ def _calculate_vertical_texture_coords(body_height: float, t: tex.Texture) -> Tu
# - error acceptable?
if t.v_cuts_meters[0] <= body_height <= t.v_size_meters:
if t.v_align_bottom or parameters.BUILDING_FAKE_AMBIENT_OCCLUSION:
logging.verbose("from bottom")
logging.debug("from bottom")
for i in range(len(t.v_cuts_meters)):
if t.v_cuts_meters[i] >= body_height:
tex_coord_bottom = 0
......
......@@ -117,7 +117,7 @@ class ClusterContainer(object):
return the_cluster
def write_statistics_for_buildings(self, clusters_name: str) -> None:
if parameters.log_level_debug_or_lower() and parameters.WRITE_CLUSTER_STATS:
if utils.utilities.log_level_debug_or_lower() and parameters.WRITE_CLUSTER_STATS:
my_file = open(os.path.join(parameters.PREFIX, clusters_name + ".dat"), "w")
for j in range(self.max_grid.iy):
for i in range(self.max_grid.ix):
......
......@@ -58,15 +58,21 @@ Calling the batch process is then pretty easy in just one step:
Mandatory command line arguments:
* ``-b``: the boundary as an underscore delimited string WEST_SOUTH_EAST_NORTH like 9.1_47.0_11_48.8 (use '.' as decimal separator). If the Western longitude is negative (e.g. in Americas), then use an asterisk character (``*``) in front (e.g. ``-b *-71.25_42.25_-70.75_42.5`` for the Boston Logan airport KBOS).
* ``-f``: the relative path to the main params.ini file. Remember that the paths are relative to the ``WORKING_DIRECTORY``.
* ``-p``: number of parallel processes (should not be more than the number of cores/CPUs) and might be constrained by memory
* ``-b BOUNDARY``: the boundary as an underscore delimited string WEST_SOUTH_EAST_NORTH like 9.1_47.0_11_48.8 (use '.' as decimal separator). If the Western longitude is negative (e.g. in Americas), then use an asterisk character (``*``) in front (e.g. ``-b *-71.25_42.25_-70.75_42.5`` for the Boston Logan airport KBOS).
* ``-f FILE_PATH``: the relative path to the main params.ini file. Remember that the paths are relative to the ``WORKING_DIRECTORY``.
* ``-p NUMBER``: number of parallel processes (should not be more than the number of cores/CPUs) and might be constrained by memory
Optional arguments:
* ``-h``, ``--help``: show a help message and exit
* ``-l`` LOGLEVEL, ``--loglevel`` LOGLEVEL: sets the loglevel. Valid levels are VERBOSE, DEBUG, INFO, WARNING, ERROR, CRITICAL
* ``-e`` PROCEDURE, ``--execute`` PROCEDURE: execute only the given procedure[s]. Otherwise everything is generated (subject to refinement by :ref:`parameters<chapter-parameters-pylons_details>`, not arguments):
* ``-m NUMBER``: the maximum of child tasks a worker process completes before it will exit. Unless you know what you are doing and have problems with constantly increasing use of resources, then do not specify a value here (otherwise start with assigning the most conservative value of 1). The default is unlimited.
* ``-l LOGLEVEL``, ``--loglevel LOGLEVEL``: sets the logging level. Valid levels are DEBUG, INFO, WARNING, ERROR, CRITICAL
* ``-o``, ``--logtofile``: writes the logging information into files in the working directory. There will be a set of log files:
+ ``osm2city-exceptions.log``: is always existing and appended to whenever a tile cannot be processed due to an exception. You should consider deleting the file whenever you are done processing and satisfied with the result. But have first a look at it to make sure that all tiles actually got processed (tile index number and processing time get stored if something is wrong along with the exception)
+ ``osm2city_main_YYYY-MM-DD_hhmmss.log`` (e.g. osm2city_main_2017-12-28_222432.log): the main process splitting the area up into tiles and assigning to sub-processes. Gives an idea about the overall processing on a per tile level.
+ ``osm2city_process_SpawnPoolWorker-#_YYYY-MM-DD_hhmmss.log`` (e.g. osm2city_process_SpawnPoolWorker-2_2017-12-28_222442.log): the detailed processing log. Unless you have specified argument ``-m`` then there will be as many files as there are processes as per argument ``-p NUMBER``.
* ``-e PROCEDURE``, ``--execute PROCEDURE``: execute only the given procedure[s]. Otherwise everything is generated i.e. ``main`` and ``details`` (subject to refinement by :ref:`parameters<chapter-parameters-pylons_details>`, not arguments):
+ ``buildings``: generates buildings
+ ``roads``: generates different types of roads and railway lines
......
......@@ -13,6 +13,7 @@ import numpy as np
import parameters
import pySkeleton.polygon as polygon
import utils.utilities
from utils import utilities
from utils.vec2d import Vec2d
......@@ -48,7 +49,7 @@ def myskel(out, b, stats: utilities.Stats, offset_xy=Vec2d(0, 0), offset_z=0., h
logging.debug("ERROR: while creating 3d roof (OSM_ID %s, %s)" % (b.osm_id, reason))
stats.roof_errors += 1
gp = parameters.get_repl_prefix() + '_roof-error-%04i' % stats.roof_errors
if parameters.log_level_debug_or_lower():
if utils.utilities.log_level_debug_or_lower():
_write_one_gp(b.pts_outer, b.osm_id, gp)
return False
......
......@@ -18,6 +18,7 @@ import re
import sys
import traceback
import types
from typing import Optional
import textures.road
from utils import vec2d as v
......@@ -31,8 +32,6 @@ import utils.utilities as utils
# =============================================================================
# PARAMETERS FOR ALL osm2city MODULES
# =============================================================================
LOGLEVEL = "INFO"
# -- Scenery folder, typically a geographic name or the ICAO code of the airport
PREFIX = "LSZR"
......@@ -318,7 +317,7 @@ def show():
"""
Prints all parameters as key = value if log level is INFO or lower
"""
if log_level_info_or_lower():
if utils.log_level_info_or_lower():
print('--- Using the following parameters: ---')
my_globals = globals()
for k in sorted(my_globals.keys()):
......@@ -407,34 +406,6 @@ def set_boundary(boundary_west: float, boundary_south: float,
BOUNDARY_NORTH = boundary_north
def set_loglevel(args_loglevel=None) -> None:
"""Set loglevel from parameters or command line."""
global LOGLEVEL
if args_loglevel is not None:
LOGLEVEL = args_loglevel
LOGLEVEL = LOGLEVEL.upper()
# -- add another log level VERBOSE. Use this when logging stuff in loops, e.g. per-OSM-object,
# potentially flooding the screen
logging.VERBOSE = 5
logging.addLevelName(logging.VERBOSE, "VERBOSE")
logging.Logger.verbose = lambda inst, msg, *args, **kwargs: inst.log(logging.VERBOSE, msg, *args, **kwargs)
logging.verbose = lambda msg, *args, **kwargs: logging.log(logging.VERBOSE, msg, *args, **kwargs)
numeric_level = getattr(logging, LOGLEVEL, None)
if not isinstance(numeric_level, int):
raise ValueError('Invalid log level: %s' % LOGLEVEL)
logging.basicConfig(level=numeric_level)
logging.getLogger().setLevel(LOGLEVEL)
def log_level_info_or_lower():
return logging.getLogger().level <= logging.INFO
def log_level_debug_or_lower():
return logging.getLogger().level <= logging.DEBUG
if __name__ == "__main__":
# Handling arguments and parameters
parser = argparse.ArgumentParser(
......
......@@ -330,16 +330,20 @@ if __name__ == "__main__":
parser = argparse.ArgumentParser(description="texture manager either reads existing texture atlas or creates new")
parser.add_argument("-f", "--file", dest="filename",
help="read parameters from FILE (e.g. params.ini)", metavar="FILE", required=True)
parser.add_argument("-l", "--loglevel",
help="set loglevel. Valid levels are VERBOSE, DEBUG, INFO, WARNING, ERROR, CRITICAL",
parser.add_argument("-l", "--loglevel", dest='loglevel',
help="set logging level. Valid levels are DEBUG, INFO (default), WARNING, ERROR, CRITICAL",
required=False)
parser.add_argument("-u", "--update", dest="update", action="store_true",
help="update texture atlas instead of creating new", required=False)
args = parser.parse_args()
log_level = 'INFO'
if args.loglevel:
log_level = args.loglevel
logging.getLogger().setLevel(log_level)
if args.filename is not None:
parameters.read_from_file(args.filename)
parameters.set_loglevel(args.loglevel) # -- must go after reading params file
parameters.show()
init_mode = InitMode.create
......
......@@ -382,7 +382,7 @@ class RoofManager(object):
can_material = False
if req_material is not None:
for prov_material in prov_materials:
logging.verbose("Provides ", prov_material, " Requires ", requires)
logging.debug("Provides ", prov_material, " Requires ", requires)
if prov_material in requires:
can_material = True
break
......@@ -404,8 +404,8 @@ class RoofManager(object):
if can_use:
candidates.append(candidate)
else:
logging.verbose(" unmet requires %s req %s prov %s",
str(candidate.filename), str(requires), str(candidate.provides))
logging.debug(" unmet requires %s req %s prov %s",
str(candidate.filename), str(requires), str(candidate.provides))
return candidates
def __str__(self):
......@@ -423,8 +423,8 @@ class FacadeManager(RoofManager):
def find_matching_facade(self, requires: List[str], tags: Dict[str, str], height: float, width: float,
stats: Stats=None) -> Optional[Texture]:
exclusions = []
#if 'roof:colour' in tags: FIXME why would we need this at all?
#exclusions.append("%s:%s" % ('roof:colour', tags['roof:colour']))
# if 'roof:colour' in tags: FIXME why would we need this at all?
# exclusions.append("%s:%s" % ('roof:colour', tags['roof:colour']))
candidates = self.find_facade_candidates(requires, exclusions, height, width)
if not candidates:
# Break down requirements to something that matches
......@@ -436,7 +436,8 @@ class FacadeManager(RoofManager):
# Now we're really desperate - just find something!
candidates = self.find_facade_candidates(['compat:roof-flat'], exclusions, height, width)
if not candidates:
logging.debug("WARNING: no matching facade texture for %1.f m x %1.1f m <%s>", height, width, str(requires))
logging.debug("WARNING: no matching facade texture for %1.f m x %1.1f m <%s>",
height, width, str(requires))
return None
ranked_list = _rank_candidates(candidates, tags)
the_texture = ranked_list[random.randint(0, len(ranked_list) - 1)]
......@@ -451,12 +452,12 @@ class FacadeManager(RoofManager):
new_candidates = []
for t in candidates:
if height < t.height_min or height > t.height_max:
logging.verbose("height %.2f (%.2f-%.2f) outside bounds : %s",
height, t.height_min, t.height_max, str(t.filename))
logging.debug("height %.2f (%.2f-%.2f) outside bounds : %s",
height, t.height_min, t.height_max, str(t.filename))
continue
if width < t.width_min or width > t.width_max:
logging.verbose("width %.2f (%.2f-%.2f) outside bounds : %s",
width, t.width_min, t.width_max, str(t.filename))
logging.debug("width %.2f (%.2f-%.2f) outside bounds : %s",
width, t.width_min, t.width_max, str(t.filename))
continue
new_candidates.append(t)
......
......@@ -3,6 +3,7 @@ Diverse utility methods used throughout osm2city and not having a clear other ho
"""
from collections import defaultdict
import datetime
import enum
import logging
import math
......@@ -94,6 +95,12 @@ def is_linux_or_mac() -> bool:
return False
def date_time_now() -> str:
"""Date and time as of now formatted as a string incl. seconds."""
today = datetime.datetime.now()
return today.strftime("%Y-%m-%d_%H%M%S")
def replace_with_os_separator(path: str) -> str:
"""Switches forward and backward slash depending on os."""
my_string = path.replace("/", os.sep)
......@@ -101,6 +108,14 @@ def replace_with_os_separator(path: str) -> str:
return my_string
def log_level_info_or_lower():
return logging.getLogger().level <= logging.INFO
def log_level_debug_or_lower():
return logging.getLogger().level <= logging.DEBUG
def match_local_coords_with_global_nodes(local_list: List[Tuple[float, float]], ref_list: List[int],
all_nodes: Dict[int, osmparser.Node],
coords_transform: coordinates.Transformation, osm_id: int,
......@@ -196,16 +211,13 @@ class Stats(object):
self.textures_total[str(texture.filename)] += 1
def print_summary(self):
if not parameters.log_level_info_or_lower():
return
out = sys.stdout
total_written = self.LOD.sum()
lodzero = 0
lodone = 0
if total_written > 0:
lodzero = 100.*self.LOD[0] / total_written
lodone = 100.*self.LOD[1] / total_written
out.write(textwrap.dedent("""
logging.info(textwrap.dedent("""
total buildings %i
parse errors %i
written %i
......@@ -220,28 +232,28 @@ class Stats(object):
roof_line = " roof-types"
for roof_shape in self.roof_shapes:
roof_line += """\n %s\t%i""" % (roof_shape, self.roof_shapes[roof_shape])
out.write(textwrap.dedent(roof_line))
logging.info(textwrap.dedent(roof_line))
textures_used = {k: v for k, v in self.textures_total.items() if v > 0}
textures_notused = {k: v for k, v in self.textures_total.items() if v == 0}
textures_not_used = {k: v for k, v in self.textures_total.items() if v == 0}
try:
textures_used_percent = len(textures_used) * 100. / len(self.textures_total)
except:
textures_used_percent = 99.9
out.write(textwrap.dedent("""
used tex %i out of %i (%2.0f %%)""" % (len(textures_used), len(self.textures_total), textures_used_percent)))
out.write(textwrap.dedent("""
logging.info(textwrap.dedent("""
used tex %i out of %i (%2.0f %%)""" % (len(textures_used), len(self.textures_total), textures_used_percent)))
logging.info(textwrap.dedent("""
Used Textures : """))
for item in sorted(list(textures_used.items()), key=lambda item: item[1], reverse=True):
out.write(textwrap.dedent("""
logging.info(textwrap.dedent("""
%i %s""" % (item[1], item[0])))
out.write(textwrap.dedent("""
logging.info(textwrap.dedent("""
Unused Textures : """))
for item in sorted(list(textures_notused.items()), key=lambda item: item[1], reverse=True):
out.write(textwrap.dedent("""
for item in sorted(list(textures_not_used.items()), key=lambda item: item[1], reverse=True):
logging.info(textwrap.dedent("""
%i %s""" % (item[1], item[0])))
out.write(textwrap.dedent("""
logging.info(textwrap.dedent("""
complex %i
roof_errors %i
ground nodes %i
......@@ -256,23 +268,21 @@ class Stats(object):
self.vertices, self.surfaces,
self.LOD[0], lodzero,
self.LOD[1], lodone)))
out.write("\narea >=\n")
logging.info("area >=")
max_area_above = max(1, self.area_above.max())
for i in range(len(self.area_levels)):
out.write(" %5g m^2 %5i |%s\n" % (self.area_levels[i], self.area_above[i],
"#" * int(56. * self.area_above[i] / max_area_above)))
logging.info(" %5g m^2 %5i |%s" % (self.area_levels[i], self.area_above[i],
"#" * int(56. * self.area_above[i] / max_area_above)))
if logging.getLogger().level <= logging.VERBOSE: # @UndefinedVariable
for name in sorted(self.textures_used):
out.write("%s\n" % name)
if log_level_debug_or_lower():
for name in sorted(textures_used):
logging.info("%s" % name)
out.write("\nnumber of corners >=\n")
logging.info("number of corners >=")
max_corners = max(1, self.corners.max())
for i in range(3, len(self.corners)):
out.write(" %2i %6i |%s\n" % (i, self.corners[i],
"#" * int(56. * self.corners[i] / max_corners)))
out.write(" complex %5i |%s\n" % (self.corners[0],
"#" * int(56. * self.corners[0] / max_corners)))
logging.info(" %2i %6i |%s" % (i, self.corners[i], "#" * int(56. * self.corners[i] / max_corners)))
logging.info(" complex %5i |%s" % (self.corners[0], "#" * int(56. * self.corners[0] / max_corners)))
class Troubleshoot:
......@@ -463,7 +473,7 @@ class FGElev(object):
def progress(i, max_i):
"""progress indicator"""
if sys.stdout.isatty() and parameters.log_level_info_or_lower():
if sys.stdout.isatty() and log_level_info_or_lower():
try:
if i % (max_i / 100) > 0:
return
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment