osm_lcm/lcm.py

   1 #!/usr/bin/python3
   2 # -*- coding: utf-8 -*-
   3
   4 ##
   5 # Copyright 2018 Telefonica S.A.
   6 #
   7 # Licensed under the Apache License, Version 2.0 (the "License"); you may
   8 # not use this file except in compliance with the License. You may obtain
   9 # a copy of the License at
  10 #
  11 #         http://www.apache.org/licenses/LICENSE-2.0
  12 #
  13 # Unless required by applicable law or agreed to in writing, software
  14 # distributed under the License is distributed on an "AS IS" BASIS, WITHOUT
  15 # WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. See the
  16 # License for the specific language governing permissions and limitations
  17 # under the License.
  18 ##
  19
  20 import asyncio
  21 import yaml
  22 import logging
  23 import logging.handlers
  24 import getopt
  25 import sys
  26 import ROclient
  27 import ns
  28 import vim_sdn
  29 import netslice
  30 from lcm_utils import versiontuple, LcmException, TaskRegistry
  31
  32 # from osm_lcm import version as lcm_version, version_date as lcm_version_date, ROclient
  33 from osm_common import dbmemory, dbmongo, fslocal, msglocal, msgkafka
  34 from osm_common import version as common_version
  35 from osm_common.dbbase import DbException
  36 from osm_common.fsbase import FsException
  37 from osm_common.msgbase import MsgException
  38 from os import environ, path
  39 from n2vc import version as n2vc_version
  40
  41
  42 __author__ = "Alfonso Tierno"
  43 min_RO_version = [0, 6, 0]
  44 min_n2vc_version = "0.0.2"
  45 min_common_version = "0.1.11"
  46 # uncomment if LCM is installed as library and installed, and get them from __init__.py
  47 lcm_version = '0.1.28'
  48 lcm_version_date = '2018-11-29'
  49
  50
  51 class Lcm:
  52
  53     ping_interval_pace = 120  # how many time ping is send once is confirmed all is running
  54     ping_interval_boot = 5    # how many time ping is sent when booting
  55
  56     def __init__(self, config_file, loop=None):
  57         """
  58         Init, Connect to database, filesystem storage, and messaging
  59         :param config: two level dictionary with configuration. Top level should contain 'database', 'storage',
  60         :return: None
  61         """
  62
  63         self.db = None
  64         self.msg = None
  65         self.fs = None
  66         self.pings_not_received = 1
  67
  68         # contains created tasks/futures to be able to cancel
  69         self.lcm_tasks = TaskRegistry()
  70         # logging
  71         self.logger = logging.getLogger('lcm')
  72         # load configuration
  73         config = self.read_config_file(config_file)
  74         self.config = config
  75         self.ro_config = {
  76             "endpoint_url": "http://{}:{}/openmano".format(config["RO"]["host"], config["RO"]["port"]),
  77             "tenant": config.get("tenant", "osm"),
  78             "logger_name": "lcm.ROclient",
  79             "loglevel": "ERROR",
  80         }
  81
  82         self.vca_config = config["VCA"]
  83
  84         self.loop = loop or asyncio.get_event_loop()
  85
  86         # logging
  87         log_format_simple = "%(asctime)s %(levelname)s %(name)s %(filename)s:%(lineno)s %(message)s"
  88         log_formatter_simple = logging.Formatter(log_format_simple, datefmt='%Y-%m-%dT%H:%M:%S')
  89         config["database"]["logger_name"] = "lcm.db"
  90         config["storage"]["logger_name"] = "lcm.fs"
  91         config["message"]["logger_name"] = "lcm.msg"
  92         if config["global"].get("logfile"):
  93             file_handler = logging.handlers.RotatingFileHandler(config["global"]["logfile"],
  94                                                                 maxBytes=100e6, backupCount=9, delay=0)
  95             file_handler.setFormatter(log_formatter_simple)
  96             self.logger.addHandler(file_handler)
  97         if not config["global"].get("nologging"):
  98             str_handler = logging.StreamHandler()
  99             str_handler.setFormatter(log_formatter_simple)
 100             self.logger.addHandler(str_handler)
 101
 102         if config["global"].get("loglevel"):
 103             self.logger.setLevel(config["global"]["loglevel"])
 104
 105         # logging other modules
 106         for k1, logname in {"message": "lcm.msg", "database": "lcm.db", "storage": "lcm.fs"}.items():
 107             config[k1]["logger_name"] = logname
 108             logger_module = logging.getLogger(logname)
 109             if config[k1].get("logfile"):
 110                 file_handler = logging.handlers.RotatingFileHandler(config[k1]["logfile"],
 111                                                                     maxBytes=100e6, backupCount=9, delay=0)
 112                 file_handler.setFormatter(log_formatter_simple)
 113                 logger_module.addHandler(file_handler)
 114             if config[k1].get("loglevel"):
 115                 logger_module.setLevel(config[k1]["loglevel"])
 116         self.logger.critical("starting osm/lcm version {} {}".format(lcm_version, lcm_version_date))
 117
 118         # check version of N2VC
 119         # TODO enhance with int conversion or from distutils.version import LooseVersion
 120         # or with list(map(int, version.split(".")))
 121         if versiontuple(n2vc_version) < versiontuple(min_n2vc_version):
 122             raise LcmException("Not compatible osm/N2VC version '{}'. Needed '{}' or higher".format(
 123                 n2vc_version, min_n2vc_version))
 124         # check version of common
 125         if versiontuple(common_version) < versiontuple(min_common_version):
 126             raise LcmException("Not compatible osm/common version '{}'. Needed '{}' or higher".format(
 127                 common_version, min_common_version))
 128
 129         try:
 130             # TODO check database version
 131             if config["database"]["driver"] == "mongo":
 132                 self.db = dbmongo.DbMongo()
 133                 self.db.db_connect(config["database"])
 134             elif config["database"]["driver"] == "memory":
 135                 self.db = dbmemory.DbMemory()
 136                 self.db.db_connect(config["database"])
 137             else:
 138                 raise LcmException("Invalid configuration param '{}' at '[database]':'driver'".format(
 139                     config["database"]["driver"]))
 140
 141             if config["storage"]["driver"] == "local":
 142                 self.fs = fslocal.FsLocal()
 143                 self.fs.fs_connect(config["storage"])
 144             else:
 145                 raise LcmException("Invalid configuration param '{}' at '[storage]':'driver'".format(
 146                     config["storage"]["driver"]))
 147
 148             if config["message"]["driver"] == "local":
 149                 self.msg = msglocal.MsgLocal()
 150                 self.msg.connect(config["message"])
 151             elif config["message"]["driver"] == "kafka":
 152                 self.msg = msgkafka.MsgKafka()
 153                 self.msg.connect(config["message"])
 154             else:
 155                 raise LcmException("Invalid configuration param '{}' at '[message]':'driver'".format(
 156                     config["storage"]["driver"]))
 157         except (DbException, FsException, MsgException) as e:
 158             self.logger.critical(str(e), exc_info=True)
 159             raise LcmException(str(e))
 160
 161         self.ns = ns.NsLcm(self.db, self.msg, self.fs, self.lcm_tasks, self.ro_config, self.vca_config, self.loop)
 162         self.netslice = netslice.NetsliceLcm(self.db, self.msg, self.fs, self.lcm_tasks, self.ro_config,
 163                                              self.vca_config, self.loop)
 164         self.vim = vim_sdn.VimLcm(self.db, self.msg, self.fs, self.lcm_tasks, self.ro_config, self.loop)
 165         self.wim = vim_sdn.WimLcm(self.db, self.msg, self.fs, self.lcm_tasks, self.ro_config, self.loop)
 166         self.sdn = vim_sdn.SdnLcm(self.db, self.msg, self.fs, self.lcm_tasks, self.ro_config, self.loop)
 167
 168     async def check_RO_version(self):
 169         try:
 170             RO = ROclient.ROClient(self.loop, **self.ro_config)
 171             RO_version = await RO.get_version()
 172             if RO_version < min_RO_version:
 173                 raise LcmException("Not compatible osm/RO version '{}.{}.{}'. Needed '{}.{}.{}' or higher".format(
 174                     *RO_version, *min_RO_version
 175                 ))
 176         except ROclient.ROClientException as e:
 177             error_text = "Error while conneting to osm/RO " + str(e)
 178             self.logger.critical(error_text, exc_info=True)
 179             raise LcmException(error_text)
 180
 181     async def test(self, param=None):
 182         self.logger.debug("Starting/Ending test task: {}".format(param))
 183
 184     async def kafka_ping(self):
 185         self.logger.debug("Task kafka_ping Enter")
 186         consecutive_errors = 0
 187         first_start = True
 188         kafka_has_received = False
 189         self.pings_not_received = 1
 190         while True:
 191             try:
 192                 await self.msg.aiowrite("admin", "ping", {"from": "lcm", "to": "lcm"}, self.loop)
 193                 # time between pings are low when it is not received and at starting
 194                 wait_time = self.ping_interval_boot if not kafka_has_received else self.ping_interval_pace
 195                 if not self.pings_not_received:
 196                     kafka_has_received = True
 197                 self.pings_not_received += 1
 198                 await asyncio.sleep(wait_time, loop=self.loop)
 199                 if self.pings_not_received > 10:
 200                     raise LcmException("It is not receiving pings from Kafka bus")
 201                 consecutive_errors = 0
 202                 first_start = False
 203             except LcmException:
 204                 raise
 205             except Exception as e:
 206                 # if not first_start is the first time after starting. So leave more time and wait
 207                 # to allow kafka starts
 208                 if consecutive_errors == 8 if not first_start else 30:
 209                     self.logger.error("Task kafka_read task exit error too many errors. Exception: {}".format(e))
 210                     raise
 211                 consecutive_errors += 1
 212                 self.logger.error("Task kafka_read retrying after Exception {}".format(e))
 213                 wait_time = 1 if not first_start else 5
 214                 await asyncio.sleep(wait_time, loop=self.loop)
 215
 216     async def kafka_read(self):
 217         self.logger.debug("Task kafka_read Enter")
 218         order_id = 1
 219         # future = asyncio.Future()
 220         consecutive_errors = 0
 221         first_start = True
 222         while consecutive_errors < 10:
 223             try:
 224                 topics = ("admin", "ns", "vim_account", "wim_account", "sdn", "nsi")
 225                 topic, command, params = await self.msg.aioread(topics, self.loop)
 226                 if topic != "admin" and command != "ping":
 227                     self.logger.debug("Task kafka_read receives {} {}: {}".format(topic, command, params))
 228                 consecutive_errors = 0
 229                 first_start = False
 230                 order_id += 1
 231                 if command == "exit":
 232                     print("Bye!")
 233                     break
 234                 elif command.startswith("#"):
 235                     continue
 236                 elif command == "echo":
 237                     # just for test
 238                     print(params)
 239                     sys.stdout.flush()
 240                     continue
 241                 elif command == "test":
 242                     asyncio.Task(self.test(params), loop=self.loop)
 243                     continue
 244
 245                 if topic == "admin":
 246                     if command == "ping" and params["to"] == "lcm" and params["from"] == "lcm":
 247                         self.pings_not_received = 0
 248                     continue
 249                 elif topic == "ns":
 250                     if command == "instantiate":
 251                         # self.logger.debug("Deploying NS {}".format(nsr_id))
 252                         nslcmop = params
 253                         nslcmop_id = nslcmop["_id"]
 254                         nsr_id = nslcmop["nsInstanceId"]
 255                         task = asyncio.ensure_future(self.ns.instantiate(nsr_id, nslcmop_id))
 256                         self.lcm_tasks.register("ns", nsr_id, nslcmop_id, "ns_instantiate", task)
 257                         continue
 258                     elif command == "terminate":
 259                         # self.logger.debug("Deleting NS {}".format(nsr_id))
 260                         nslcmop = params
 261                         nslcmop_id = nslcmop["_id"]
 262                         nsr_id = nslcmop["nsInstanceId"]
 263                         self.lcm_tasks.cancel(topic, nsr_id)
 264                         task = asyncio.ensure_future(self.ns.terminate(nsr_id, nslcmop_id))
 265                         self.lcm_tasks.register("ns", nsr_id, nslcmop_id, "ns_terminate", task)
 266                         continue
 267                     elif command == "action":
 268                         # self.logger.debug("Update NS {}".format(nsr_id))
 269                         nslcmop = params
 270                         nslcmop_id = nslcmop["_id"]
 271                         nsr_id = nslcmop["nsInstanceId"]
 272                         task = asyncio.ensure_future(self.ns.action(nsr_id, nslcmop_id))
 273                         self.lcm_tasks.register("ns", nsr_id, nslcmop_id, "ns_action", task)
 274                         continue
 275                     elif command == "scale":
 276                         # self.logger.debug("Update NS {}".format(nsr_id))
 277                         nslcmop = params
 278                         nslcmop_id = nslcmop["_id"]
 279                         nsr_id = nslcmop["nsInstanceId"]
 280                         task = asyncio.ensure_future(self.ns.scale(nsr_id, nslcmop_id))
 281                         self.lcm_tasks.register("ns", nsr_id, nslcmop_id, "ns_scale", task)
 282                         continue
 283                     elif command == "show":
 284                         try:
 285                             db_nsr = self.db.get_one("nsrs", {"_id": nsr_id})
 286                             print("nsr:\n    _id={}\n    operational-status: {}\n    config-status: {}"
 287                                   "\n    detailed-status: {}\n    deploy: {}\n    tasks: {}"
 288                                   "".format(nsr_id, db_nsr["operational-status"], db_nsr["config-status"],
 289                                             db_nsr["detailed-status"],
 290                                             db_nsr["_admin"]["deployed"], self.lcm_ns_tasks.get(nsr_id)))
 291                         except Exception as e:
 292                             print("nsr {} not found: {}".format(nsr_id, e))
 293                         sys.stdout.flush()
 294                         continue
 295                     elif command == "deleted":
 296                         continue  # TODO cleaning of task just in case should be done
 297                     elif command in ("terminated", "instantiated", "scaled", "actioned"):  # "scaled-cooldown-time"
 298                         continue
 299                 elif topic == "nsi":  # netslice LCM processes (instantiate, terminate, etc)
 300                     if command == "instantiate":
 301                         # self.logger.debug("Instantiating Network Slice {}".format(nsilcmop["netsliceInstanceId"]))
 302                         nsilcmop = params
 303                         nsilcmop_id = nsilcmop["_id"]                               # slice operation id
 304                         nsir_id = nsilcmop["netsliceInstanceId"]                    # slice record id
 305                         task = asyncio.ensure_future(self.netslice.instantiate(nsir_id, nsilcmop_id))
 306                         self.lcm_tasks.register("nsi", nsir_id, nsilcmop_id, "nsi_instantiate", task)
 307                         continue
 308                     elif command == "terminate":
 309                         # self.logger.debug("Terminating Network Slice NS {}".format(nsilcmop["netsliceInstanceId"]))
 310                         nsilcmop = params
 311                         nsilcmop_id = nsilcmop["_id"]                               # slice operation id
 312                         nsir_id = nsilcmop["netsliceInstanceId"]                    # slice record id
 313                         self.lcm_tasks.cancel(topic, nsir_id)
 314                         task = asyncio.ensure_future(self.netslice.terminate(nsir_id, nsilcmop_id))
 315                         self.lcm_tasks.register("nsi", nsir_id, nsilcmop_id, "nsi_terminate", task)
 316                         continue
 317                     elif command == "show":
 318                         try:
 319                             db_nsir = self.db.get_one("nsirs", {"_id": nsir_id})
 320                             print("nsir:\n    _id={}\n    operational-status: {}\n    config-status: {}"
 321                                   "\n    detailed-status: {}\n    deploy: {}\n    tasks: {}"
 322                                   "".format(nsir_id, db_nsir["operational-status"], db_nsir["config-status"],
 323                                             db_nsir["detailed-status"],
 324                                             db_nsir["_admin"]["deployed"], self.lcm_netslice_tasks.get(nsir_id)))
 325                         except Exception as e:
 326                             print("nsir {} not found: {}".format(nsir_id, e))
 327                         sys.stdout.flush()
 328                         continue
 329                     elif command == "deleted":
 330                         continue  # TODO cleaning of task just in case should be done
 331                     elif command in ("terminated", "instantiated", "scaled", "actioned"):  # "scaled-cooldown-time"
 332                         continue
 333                 elif topic == "vim_account":
 334                     vim_id = params["_id"]
 335                     if command == "create":
 336                         task = asyncio.ensure_future(self.vim.create(params, order_id))
 337                         self.lcm_tasks.register("vim_account", vim_id, order_id, "vim_create", task)
 338                         continue
 339                     elif command == "delete":
 340                         self.lcm_tasks.cancel(topic, vim_id)
 341                         task = asyncio.ensure_future(self.vim.delete(vim_id, order_id))
 342                         self.lcm_tasks.register("vim_account", vim_id, order_id, "vim_delete", task)
 343                         continue
 344                     elif command == "show":
 345                         print("not implemented show with vim_account")
 346                         sys.stdout.flush()
 347                         continue
 348                     elif command == "edit":
 349                         task = asyncio.ensure_future(self.vim.edit(params, order_id))
 350                         self.lcm_tasks.register("vim_account", vim_id, order_id, "vim_edit", task)
 351                         continue
 352                 elif topic == "wim_account":
 353                     wim_id = params["_id"]
 354                     if command == "create":
 355                         task = asyncio.ensure_future(self.wim.create(params, order_id))
 356                         self.lcm_tasks.register("wim_account", wim_id, order_id, "wim_create", task)
 357                         continue
 358                     elif command == "delete":
 359                         self.lcm_tasks.cancel(topic, wim_id)
 360                         task = asyncio.ensure_future(self.wim.delete(wim_id, order_id))
 361                         self.lcm_tasks.register("wim_account", wim_id, order_id, "wim_delete", task)
 362                         continue
 363                     elif command == "show":
 364                         print("not implemented show with wim_account")
 365                         sys.stdout.flush()
 366                         continue
 367                     elif command == "edit":
 368                         task = asyncio.ensure_future(self.wim.edit(params, order_id))
 369                         self.lcm_tasks.register("wim_account", wim_id, order_id, "wim_edit", task)
 370                         continue
 371                 elif topic == "sdn":
 372                     _sdn_id = params["_id"]
 373                     if command == "create":
 374                         task = asyncio.ensure_future(self.sdn.create(params, order_id))
 375                         self.lcm_tasks.register("sdn", _sdn_id, order_id, "sdn_create", task)
 376                         continue
 377                     elif command == "delete":
 378                         self.lcm_tasks.cancel(topic, _sdn_id)
 379                         task = asyncio.ensure_future(self.sdn.delete(_sdn_id, order_id))
 380                         self.lcm_tasks.register("sdn", _sdn_id, order_id, "sdn_delete", task)
 381                         continue
 382                     elif command == "edit":
 383                         task = asyncio.ensure_future(self.sdn.edit(params, order_id))
 384                         self.lcm_tasks.register("sdn", _sdn_id, order_id, "sdn_edit", task)
 385                         continue
 386                 self.logger.critical("unknown topic {} and command '{}'".format(topic, command))
 387             except Exception as e:
 388                 # if not first_start is the first time after starting. So leave more time and wait
 389                 # to allow kafka starts
 390                 if consecutive_errors == 8 if not first_start else 30:
 391                     self.logger.error("Task kafka_read task exit error too many errors. Exception: {}".format(e))
 392                     raise
 393                 consecutive_errors += 1
 394                 self.logger.error("Task kafka_read retrying after Exception {}".format(e))
 395                 wait_time = 2 if not first_start else 5
 396                 await asyncio.sleep(wait_time, loop=self.loop)
 397
 398         # self.logger.debug("Task kafka_read terminating")
 399         self.logger.debug("Task kafka_read exit")
 400
 401     def health_check(self):
 402
 403         global exit_code
 404         task = None
 405         exit_code = 1
 406
 407         def health_check_callback(topic, command, params):
 408             global exit_code
 409             print("receiving callback {} {} {}".format(topic, command, params))
 410             if topic == "admin" and command == "ping" and params["to"] == "lcm" and params["from"] == "lcm":
 411                 # print("received LCM ping")
 412                 exit_code = 0
 413                 task.cancel()
 414
 415         try:
 416             task = asyncio.ensure_future(self.msg.aioread(("admin",), self.loop, health_check_callback))
 417             self.loop.run_until_complete(task)
 418         except Exception:
 419             pass
 420         exit(exit_code)
 421
 422     def start(self):
 423
 424         # check RO version
 425         self.loop.run_until_complete(self.check_RO_version())
 426
 427         self.loop.run_until_complete(asyncio.gather(
 428             self.kafka_read(),
 429             self.kafka_ping()
 430         ))
 431         # TODO
 432         # self.logger.debug("Terminating cancelling creation tasks")
 433         # self.lcm_tasks.cancel("ALL", "create")
 434         # timeout = 200
 435         # while self.is_pending_tasks():
 436         #     self.logger.debug("Task kafka_read terminating. Waiting for tasks termination")
 437         #     await asyncio.sleep(2, loop=self.loop)
 438         #     timeout -= 2
 439         #     if not timeout:
 440         #         self.lcm_tasks.cancel("ALL", "ALL")
 441         self.loop.close()
 442         self.loop = None
 443         if self.db:
 444             self.db.db_disconnect()
 445         if self.msg:
 446             self.msg.disconnect()
 447         if self.fs:
 448             self.fs.fs_disconnect()
 449
 450     def read_config_file(self, config_file):
 451         # TODO make a [ini] + yaml inside parser
 452         # the configparser library is not suitable, because it does not admit comments at the end of line,
 453         # and not parse integer or boolean
 454         try:
 455             with open(config_file) as f:
 456                 conf = yaml.load(f)
 457             for k, v in environ.items():
 458                 if not k.startswith("OSMLCM_"):
 459                     continue
 460                 k_items = k.lower().split("_")
 461                 if len(k_items) < 3:
 462                     continue
 463                 if k_items[1] in ("ro", "vca"):
 464                     # put in capital letter
 465                     k_items[1] = k_items[1].upper()
 466                 c = conf
 467                 try:
 468                     for k_item in k_items[1:-1]:
 469                         c = c[k_item]
 470                     if k_items[-1] == "port":
 471                         c[k_items[-1]] = int(v)
 472                     else:
 473                         c[k_items[-1]] = v
 474                 except Exception as e:
 475                     self.logger.warn("skipping environ '{}' on exception '{}'".format(k, e))
 476
 477             return conf
 478         except Exception as e:
 479             self.logger.critical("At config file '{}': {}".format(config_file, e))
 480             exit(1)
 481
 482
 483 def usage():
 484     print("""Usage: {} [options]
 485         -c|--config [configuration_file]: loads the configuration file (default: ./nbi.cfg)
 486         --health-check: do not run lcm, but inspect kafka bus to determine if lcm is healthy
 487         -h|--help: shows this help
 488         """.format(sys.argv[0]))
 489     # --log-socket-host HOST: send logs to this host")
 490     # --log-socket-port PORT: send logs using this port (default: 9022)")
 491
 492
 493 if __name__ == '__main__':
 494     try:
 495         # load parameters and configuration
 496         opts, args = getopt.getopt(sys.argv[1:], "hc:", ["config=", "help", "health-check"])
 497         # TODO add  "log-socket-host=", "log-socket-port=", "log-file="
 498         config_file = None
 499         health_check = None
 500         for o, a in opts:
 501             if o in ("-h", "--help"):
 502                 usage()
 503                 sys.exit()
 504             elif o in ("-c", "--config"):
 505                 config_file = a
 506             elif o == "--health-check":
 507                 health_check = True
 508             # elif o == "--log-socket-port":
 509             #     log_socket_port = a
 510             # elif o == "--log-socket-host":
 511             #     log_socket_host = a
 512             # elif o == "--log-file":
 513             #     log_file = a
 514             else:
 515                 assert False, "Unhandled option"
 516         if config_file:
 517             if not path.isfile(config_file):
 518                 print("configuration file '{}' not exist".format(config_file), file=sys.stderr)
 519                 exit(1)
 520         else:
 521             for config_file in (__file__[:__file__.rfind(".")] + ".cfg", "./lcm.cfg", "/etc/osm/lcm.cfg"):
 522                 if path.isfile(config_file):
 523                     break
 524             else:
 525                 print("No configuration file 'lcm.cfg' found neither at local folder nor at /etc/osm/", file=sys.stderr)
 526                 exit(1)
 527         lcm = Lcm(config_file)
 528         if health_check:
 529             lcm.health_check()
 530         else:
 531             lcm.start()
 532     except (LcmException, getopt.GetoptError) as e:
 533         print(str(e), file=sys.stderr)
 534         # usage()
 535         exit(1)