Browse Source

Add debug messages

We are having a hard time keeping track of which operations
correspond to which request.  This patch adds the ability to track
operations in the notifier with the message_id of the notification
being processed.  This message_id (which is generated by oslo is
a uuid

For the server, we could also set the message_id to the request_id
of the python-requests object received, but this is already
logged as part of the server logs.

Change-Id: Ie8b885a2b5cba6684e92c49eed4a99d24621402e
tags/1.2.0
Ade Lee 1 month ago
parent
commit
ade787b90c
3 changed files with 185 additions and 143 deletions
  1. 96
    79
      novajoin/ipa.py
  2. 26
    15
      novajoin/join.py
  3. 63
    49
      novajoin/notifications.py

+ 96
- 79
novajoin/ipa.py View File

@@ -62,6 +62,7 @@ class IPANovaJoinBase(object):
62 62
         self.ntries = CONF.connect_retries
63 63
         self.initial_backoff = CONF.connect_backoff
64 64
         self.ccache = "MEMORY:" + str(uuid.uuid4())
65
+        LOG.debug("cache: %s", self.ccache)
65 66
         os.environ['KRB5CCNAME'] = self.ccache
66 67
         if self._ipa_client_configured() and not api.isdone('finalize'):
67 68
             (hostname, realm) = self.get_host_and_realm()
@@ -126,23 +127,24 @@ class IPANovaJoinBase(object):
126 127
 
127 128
         return (hostname, realm)
128 129
 
129
-    def __backoff(self):
130
-        LOG.debug("Backing off %s seconds", self.backoff)
130
+    def __backoff(self, message_id):
131
+        LOG.debug("[%s] Backing off %s seconds", message_id, self.backoff)
131 132
         time.sleep(self.backoff)
132 133
         if self.backoff < 512:
133 134
             self.backoff = self.backoff * 2
134 135
 
135
-    def __reset_backoff(self):
136
+    def __reset_backoff(self, message_id):
136 137
         if self.backoff > self.initial_backoff:
137
-            LOG.debug("Resetting backoff to %d", self.initial_backoff)
138
+            LOG.debug("[%s] Resetting backoff to %d",
139
+                      message_id, self.initial_backoff)
138 140
             self.backoff = self.initial_backoff
139 141
 
140
-    def __get_connection(self):
142
+    def __get_connection(self, message_id):
141 143
         """Make a connection to IPA or raise an error."""
142 144
         tries = 0
143 145
 
144 146
         while (tries <= self.ntries):
145
-            LOG.debug("Attempt %d of %d", tries, self.ntries)
147
+            LOG.debug("[%s] Attempt %d of %d", message_id, tries, self.ntries)
146 148
             if api.Backend.rpcclient.isconnected():
147 149
                 api.Backend.rpcclient.disconnect()
148 150
             try:
@@ -154,7 +156,7 @@ class IPANovaJoinBase(object):
154 156
                     errors.TicketExpired,
155 157
                     errors.KerberosError) as e:
156 158
                 tries += 1
157
-                LOG.debug("kinit again: %s", e)
159
+                LOG.debug("[%s] kinit again: %s", message_id, e)
158 160
                 # pylint: disable=no-member
159 161
                 try:
160 162
                     kinit_keytab(str('nova/%s@%s' %
@@ -162,35 +164,37 @@ class IPANovaJoinBase(object):
162 164
                                  CONF.keytab,
163 165
                                  self.ccache)
164 166
                 except GSSError as e:
165
-                    LOG.debug("kinit failed: %s", e)
167
+                    LOG.debug("[%s] kinit failed: %s", message_id, e)
166 168
                     if self.backoff:
167
-                        self.__backoff()
169
+                        self.__backoff(message_id)
168 170
             except errors.NetworkError:
169 171
                 tries += 1
170 172
                 if self.backoff:
171
-                    self.__backoff()
173
+                    self.__backoff(message_id)
172 174
             except http_client.ResponseNotReady:
173 175
                 # NOTE(xek): This means that the server closed the socket,
174 176
                 # so keep-alive ended and we can't use that connection.
175 177
                 api.Backend.rpcclient.disconnect()
176 178
                 tries += 1
177 179
                 if self.backoff:
178
-                    self.__backoff()
180
+                    self.__backoff(message_id)
179 181
             else:
180 182
                 # successful connection
181
-                self.__reset_backoff()
183
+                self.__reset_backoff(message_id)
182 184
                 return
183 185
 
184
-        LOG.error("Failed to connect to IPA after %d attempts", self.ntries)
186
+        LOG.error("[%s] Failed to connect to IPA after %d attempts",
187
+                  message_id, self.ntries)
185 188
         raise exception.IPAConnectionError(tries=self.ntries)
186 189
 
187
-    def start_batch_operation(self):
190
+    def start_batch_operation(self, message_id=0):
188 191
         """Start a batch operation.
189 192
 
190 193
            IPA method calls will be collected in a batch job
191 194
            and submitted to IPA once all the operations have collected
192 195
            by a call to _flush_batch_operation().
193 196
         """
197
+        LOG.debug("[%s] start batch operation", message_id)
194 198
         self.batch_args = list()
195 199
 
196 200
     def _add_batch_operation(self, command, *args, **kw):
@@ -200,21 +204,21 @@ class IPANovaJoinBase(object):
200 204
             "params": [args, kw],
201 205
         })
202 206
 
203
-    def flush_batch_operation(self):
207
+    def flush_batch_operation(self, message_id=0):
204 208
         """Make an IPA batch call."""
205
-        LOG.debug("flush_batch_operation")
209
+        LOG.debug("[%] flush_batch_operation", message_id)
206 210
         if not self.batch_args:
207 211
             return None
208 212
 
209 213
         kw = {}
210
-        LOG.debug(self.batch_args)
214
+        LOG.debug("[%s] %s", message_id, self.batch_args)
211 215
 
212
-        return self._call_ipa('batch', *self.batch_args, **kw)
216
+        return self._call_ipa(message_id, 'batch', *self.batch_args, **kw)
213 217
 
214
-    def _call_ipa(self, command, *args, **kw):
218
+    def _call_ipa(self, message_id, command, *args, **kw):
215 219
         """Make an IPA call."""
216 220
         if not api.Backend.rpcclient.isconnected():
217
-            self.__get_connection()
221
+            self.__get_connection(message_id)
218 222
         if 'version' not in kw:
219 223
             kw['version'] = u'2.146'  # IPA v4.2.0 for compatibility
220 224
 
@@ -226,11 +230,11 @@ class IPANovaJoinBase(object):
226 230
             except (errors.CCacheError,
227 231
                     errors.TicketExpired,
228 232
                     errors.KerberosError):
229
-                LOG.debug("Refresh authentication")
230
-                self.__get_connection()
233
+                LOG.debug("[%s] Refresh authentication", message_id)
234
+                self.__get_connection(message_id)
231 235
             except errors.NetworkError:
232 236
                 if self.backoff:
233
-                    self.__backoff()
237
+                    self.__backoff(message_id)
234 238
                 else:
235 239
                     raise
236 240
             except http_client.ResponseNotReady:
@@ -238,7 +242,7 @@ class IPANovaJoinBase(object):
238 242
                 # so keep-alive ended and we can't use that connection.
239 243
                 api.Backend.rpcclient.disconnect()
240 244
                 if self.backoff:
241
-                    self.__backoff()
245
+                    self.__backoff(message_id)
242 246
                 else:
243 247
                     raise
244 248
 
@@ -259,7 +263,8 @@ class IPAClient(IPANovaJoinBase):
259 263
     host_cache = cachetools.TTLCache(maxsize=512, ttl=30)
260 264
     service_cache = cachetools.TTLCache(maxsize=512, ttl=30)
261 265
 
262
-    def add_host(self, hostname, ipaotp, metadata=None, image_metadata=None):
266
+    def add_host(self, hostname, ipaotp, metadata=None, image_metadata=None,
267
+                 message_id=0):
263 268
         """Add a host to IPA.
264 269
 
265 270
         If requested in the metadata, add a host to IPA. The assumption
@@ -270,10 +275,10 @@ class IPAClient(IPANovaJoinBase):
270 275
         and if that fails due to NotFound the host is added.
271 276
         """
272 277
 
273
-        LOG.debug('Adding  ' + hostname + ' to IPA.')
278
+        LOG.debug("[%s] Adding %s to IPA.", message_id, hostname)
274 279
 
275 280
         if not self._ipa_client_configured():
276
-            LOG.debug('IPA is not configured')
281
+            LOG.debug('[%s] IPA is not configured', message_id)
277 282
             return False
278 283
 
279 284
         # There's no use in doing any operations if ipalib hasn't been
@@ -287,7 +292,7 @@ class IPAClient(IPANovaJoinBase):
287 292
             image_metadata = {}
288 293
 
289 294
         if hostname in self.host_cache:
290
-            LOG.debug('Host  ' + hostname + ' found in cache.')
295
+            LOG.debug("[%s] Host  %s found in cache.", message_id, hostname)
291 296
             return self.host_cache[hostname]
292 297
 
293 298
         params = [hostname]
@@ -316,11 +321,11 @@ class IPAClient(IPANovaJoinBase):
316 321
         }
317 322
 
318 323
         try:
319
-            self._call_ipa('host_mod', *params, **modargs)
324
+            self._call_ipa(message_id, 'host_mod', *params, **modargs)
320 325
             self.host_cache[hostname] = six.text_type(ipaotp)
321 326
         except errors.NotFound:
322 327
             try:
323
-                self._call_ipa('host_add', *params, **hostargs)
328
+                self._call_ipa(message_id, 'host_add', *params, **hostargs)
324 329
                 self.host_cache[hostname] = six.text_type(ipaotp)
325 330
             except errors.DuplicateEntry:
326 331
                 # We have no idea what the OTP is for the existing host.
@@ -337,30 +342,30 @@ class IPAClient(IPANovaJoinBase):
337 342
 
338 343
         return self.host_cache.get(hostname, False)
339 344
 
340
-    def add_subhost(self, hostname):
345
+    def add_subhost(self, hostname, message_id=0):
341 346
         """Add a subhost to IPA.
342 347
 
343 348
         Servers can have multiple network interfaces, and therefore can
344 349
         have multiple aliases.  Moreover, they can part of a service using
345 350
         a virtual host (VIP).  These aliases are denoted 'subhosts',
346 351
         """
347
-        LOG.debug('Adding subhost: ' + hostname)
352
+        LOG.debug('[%s] Adding subhost: %s', message_id, hostname)
348 353
         if hostname not in self.host_cache:
349 354
             params = [hostname]
350 355
             hostargs = {'force': True}
351 356
             self._add_batch_operation('host_add', *params, **hostargs)
352 357
             self.host_cache[hostname] = True
353 358
         else:
354
-            LOG.debug('subhost  ' + hostname + ' found in cache.')
359
+            LOG.debug("[%s] subhost %s found in cache.", message_id, hostname)
355 360
 
356
-    def delete_subhost(self, hostname, batch=True):
361
+    def delete_subhost(self, hostname, batch=True, message_id=0):
357 362
         """Delete a subhost from IPA.
358 363
 
359 364
         Servers can have multiple network interfaces, and therefore can
360 365
         have multiple aliases.  Moreover, they can part of a service using
361 366
         a virtual host (VIP).  These aliases are denoted 'subhosts',
362 367
         """
363
-        LOG.debug('Deleting subhost: ' + hostname)
368
+        LOG.debug(" [%s] Deleting subhost: %s", message_id, hostname)
364 369
         host_params = [hostname]
365 370
 
366 371
         (hn, domain) = self.split_hostname(hostname)
@@ -381,19 +386,20 @@ class IPAClient(IPANovaJoinBase):
381 386
         else:
382 387
             if hostname in self.host_cache:
383 388
                 del self.host_cache[hostname]
384
-            self._call_ipa('host_del', *host_params, **host_kw)
389
+            self._call_ipa(message_id, 'host_del', *host_params, **host_kw)
385 390
             try:
386
-                self._call_ipa('dnsrecord_del', *dns_params, **dns_kw)
391
+                self._call_ipa(message_id, 'dnsrecord_del',
392
+                               *dns_params, **dns_kw)
387 393
             except (errors.NotFound, errors.ACIError):
388 394
                 # Ignore DNS deletion errors
389 395
                 pass
390 396
 
391
-    def delete_host(self, hostname, metadata=None):
397
+    def delete_host(self, hostname, metadata=None, message_id=0):
392 398
         """Delete a host from IPA and remove all related DNS entries."""
393
-        LOG.debug('Deleting ' + hostname + ' from IPA.')
399
+        LOG.debug("[%s] Deleting %s from IPA", message_id, hostname)
394 400
 
395 401
         if not self._ipa_client_configured():
396
-            LOG.debug('IPA is not configured')
402
+            LOG.debug('[%s] IPA is not configured', message_id)
397 403
             return
398 404
 
399 405
         if metadata is None:
@@ -409,7 +415,7 @@ class IPAClient(IPANovaJoinBase):
409 415
         try:
410 416
             if hostname in self.host_cache:
411 417
                 del self.host_cache[hostname]
412
-            self._call_ipa('host_del', *params, **kw)
418
+            self._call_ipa(message_id, 'host_del', *params, **kw)
413 419
         except (errors.NotFound, errors.ACIError):
414 420
             # Trying to delete a host that doesn't exist will raise an ACIError
415 421
             # to hide whether the entry exists or not
@@ -422,27 +428,28 @@ class IPAClient(IPANovaJoinBase):
422 428
         dns_kw = {'del_all': True, }
423 429
 
424 430
         try:
425
-            self._call_ipa('dnsrecord_del', *dns_params, **dns_kw)
431
+            self._call_ipa(message_id, 'dnsrecord_del', *dns_params, **dns_kw)
426 432
         except (errors.NotFound, errors.ACIError):
427 433
             # Ignore DNS deletion errors
428 434
             pass
429 435
 
430
-    def add_service(self, principal):
436
+    def add_service(self, principal, message_id=0):
431 437
         if principal not in self.service_cache:
432 438
             try:
433 439
                 (service, hostname, realm) = self.split_principal(principal)
434 440
             except errors.MalformedServicePrincipal as e:
435
-                LOG.error("Unable to split principal %s: %s", principal, e)
441
+                LOG.error("[%s] Unable to split principal %s: %s",
442
+                          message_id, principal, e)
436 443
                 raise
437
-            LOG.debug('Adding service: ' + principal)
444
+            LOG.debug("[%s] Adding service: %s", message_id, principal)
438 445
             params = [principal]
439 446
             service_args = {'force': True}
440 447
             self._add_batch_operation('service_add', *params, **service_args)
441 448
             self.service_cache[principal] = [hostname]
442 449
         else:
443
-            LOG.debug('Service ' + principal + ' found in cache.')
450
+            LOG.debug("[%s] Service %s found in cache", message_id, principal)
444 451
 
445
-    def service_add_host(self, service_principal, host):
452
+    def service_add_host(self, service_principal, host, message_id=0):
446 453
         """Add a host to a service.
447 454
 
448 455
         In IPA there is a relationship between a host and the services for
@@ -454,8 +461,8 @@ class IPAClient(IPANovaJoinBase):
454 461
         in IPA this is done using the service-add-host API.
455 462
         """
456 463
         if host not in self.service_cache.get(service_principal, []):
457
-            LOG.debug('Adding principal ' + service_principal +
458
-                      ' to host ' + host)
464
+            LOG.debug("[%s] Adding principal %s to host %s",
465
+                      message_id, service_principal, host)
459 466
             params = [service_principal]
460 467
             service_args = {'host': (host,)}
461 468
             self._add_batch_operation('service_add_host', *params,
@@ -463,17 +470,19 @@ class IPAClient(IPANovaJoinBase):
463 470
             self.service_cache[service_principal] = self.service_cache.get(
464 471
                 service_principal, []) + [host]
465 472
         else:
466
-            LOG.debug('Host ' + host + ' managing ' + service_principal +
467
-                      ' found in cache.')
473
+            LOG.debug("[%s] Host %s managing %s found in cache",
474
+                      message_id, host, service_principal)
468 475
 
469
-    def service_has_hosts(self, service_principal):
476
+    def service_has_hosts(self, service_principal, message_id=0):
470 477
         """Return True if hosts other than parent manages this service"""
471 478
 
472
-        LOG.debug('Checking if principal ' + service_principal + ' has hosts')
479
+        LOG.debug("[%s] Checking if principal %s has hosts",
480
+                  message_id, service_principal)
473 481
         params = [service_principal]
474 482
         service_args = {}
475 483
         try:
476
-            result = self._call_ipa('service_show', *params, **service_args)
484
+            result = self._call_ipa(message_id, 'service_show',
485
+                                    *params, **service_args)
477 486
         except errors.NotFound:
478 487
             raise KeyError
479 488
         serviceresult = result['result']
@@ -483,7 +492,8 @@ class IPAClient(IPANovaJoinBase):
483 492
                 service_principal
484 493
             )
485 494
         except errors.MalformedServicePrincipal as e:
486
-            LOG.error("Unable to split principal %s: %s", service_principal, e)
495
+            LOG.error("[%s] Unable to split principal %s: %s",
496
+                      message_id, service_principal, e)
487 497
             raise
488 498
 
489 499
         for candidate in serviceresult.get('managedby_host', []):
@@ -491,28 +501,30 @@ class IPAClient(IPANovaJoinBase):
491 501
                 return True
492 502
         return False
493 503
 
494
-    def host_get_services(self, service_host):
504
+    def host_get_services(self, service_host, message_id=0):
495 505
         """Return list of services this host manages"""
496
-        LOG.debug('Checking host ' + service_host + ' services')
506
+        LOG.debug("[%s] Checking host %s services", message_id, service_host)
497 507
         params = []
498 508
         service_args = {'man_by_host': six.text_type(service_host)}
499
-        result = self._call_ipa('service_find', *params, **service_args)
509
+        result = self._call_ipa(message_id, 'service_find',
510
+                                *params, **service_args)
500 511
         return [service['krbprincipalname'][0] for service in result['result']]
501 512
 
502
-    def host_has_services(self, service_host):
513
+    def host_has_services(self, service_host, message_id=0):
503 514
         """Return True if this host manages any services"""
504
-        return len(self.host_get_services(service_host)) > 0
515
+        return len(self.host_get_services(service_host, message_id)) > 0
505 516
 
506
-    def find_host(self, hostname):
517
+    def find_host(self, hostname, message_id=0):
507 518
         """Return True if this host exists"""
508
-        LOG.debug('Checking if host ' + hostname + ' exists')
519
+        LOG.debug("[%s] Checking if host %s exists", message_id, hostname)
509 520
         params = []
510 521
         service_args = {'fqdn': six.text_type(hostname)}
511
-        result = self._call_ipa('host_find', *params, **service_args)
522
+        result = self._call_ipa(message_id, 'host_find',
523
+                                *params, **service_args)
512 524
         return result['count'] > 0
513 525
 
514
-    def delete_service(self, principal, batch=True):
515
-        LOG.debug('Deleting service: ' + principal)
526
+    def delete_service(self, principal, batch=True, message_id=0):
527
+        LOG.debug("[%s] Deleting service: %s", message_id, principal)
516 528
         params = [principal]
517 529
         service_args = {}
518 530
         if batch:
@@ -522,14 +534,15 @@ class IPAClient(IPANovaJoinBase):
522 534
         else:
523 535
             if principal in self.service_cache:
524 536
                 del self.service_cache[principal]
525
-            return self._call_ipa('service_del', *params, **service_args)
537
+            return self._call_ipa(message_id, 'service_del',
538
+                                  *params, **service_args)
526 539
 
527
-    def add_ip(self, hostname, floating_ip):
540
+    def add_ip(self, hostname, floating_ip, message_id=0):
528 541
         """Add a floating IP to a given hostname."""
529
-        LOG.debug('In add_ip')
542
+        LOG.debug("[%s] In add_ip", message_id)
530 543
 
531 544
         if not self._ipa_client_configured():
532
-            LOG.debug('IPA is not configured')
545
+            LOG.debug('[%s] IPA is not configured', message_id)
533 546
             return
534 547
 
535 548
         params = [six.text_type(get_domain() + '.'),
@@ -537,35 +550,39 @@ class IPAClient(IPANovaJoinBase):
537 550
         kw = {'a_part_ip_address': six.text_type(floating_ip)}
538 551
 
539 552
         try:
540
-            self._call_ipa('dnsrecord_add', *params, **kw)
553
+            self._call_ipa(message_id, 'dnsrecord_add', *params, **kw)
541 554
         except (errors.DuplicateEntry, errors.ValidationError):
542 555
             pass
543 556
 
544
-    def find_record(self, floating_ip):
557
+    def find_record(self, floating_ip, message_id=0):
545 558
         """Find DNS A record for floating IP address"""
546
-        LOG.debug('looking up host for floating ip' + floating_ip)
559
+        LOG.debug("[%s] looking up host for floating ip %s",
560
+                  message_id, floating_ip)
547 561
         params = [six.text_type(get_domain() + '.')]
548 562
         service_args = {'arecord': six.text_type(floating_ip)}
549
-        result = self._call_ipa('dnsrecord_find', *params, **service_args)
563
+        result = self._call_ipa(message_id, 'dnsrecord_find',
564
+                                *params, **service_args)
550 565
         if result['count'] == 0:
551 566
             return
552 567
         assert(result['count'] == 1)
553 568
         return result['result'][0]['idnsname'][0].to_unicode()
554 569
 
555
-    def remove_ip(self, floating_ip):
570
+    def remove_ip(self, floating_ip, message_id=0):
556 571
         """Remove a floating IP from a given hostname."""
557
-        LOG.debug('In remove_ip')
572
+        LOG.debug("[%s] In remove_ip", message_id)
558 573
 
559 574
         if not self._ipa_client_configured():
560
-            LOG.debug('IPA is not configured')
575
+            LOG.debug("[%s] IPA is not configured", message_id)
561 576
             return
562 577
 
563
-        hostname = self.find_record(floating_ip)
578
+        hostname = self.find_record(floating_ip, message_id)
564 579
         if not hostname:
565
-            LOG.debug('floating IP record not found')
580
+            LOG.debug("[%s] floating IP record not found for %s",
581
+                      message_id, floating_ip)
566 582
             return
567 583
 
568 584
         params = [six.text_type(get_domain() + '.'), hostname]
569 585
         service_args = {'arecord': six.text_type(floating_ip)}
570 586
 
571
-        self._call_ipa('dnsrecord_del', *params, **service_args)
587
+        self._call_ipa(message_id, 'dnsrecord_del',
588
+                       *params, **service_args)

+ 26
- 15
novajoin/join.py View File

@@ -108,6 +108,12 @@ class JoinController(Controller):
108 108
 
109 109
         Options passed in but as yet-unused are and user-data.
110 110
         """
111
+
112
+        # Set message id to zero for now.
113
+        # We could set it to the request_id in the python-request,
114
+        # but this is already logged as part of the server logs.
115
+        message_id = 0
116
+
111 117
         if not body:
112 118
             LOG.error('No body in create request')
113 119
             raise base.Fault(webob.exc.HTTPBadRequest())
@@ -191,7 +197,8 @@ class JoinController(Controller):
191 197
 
192 198
         try:
193 199
             data['ipaotp'] = self.ipaclient.add_host(data['hostname'], ipaotp,
194
-                                                     metadata, image_metadata)
200
+                                                     metadata, image_metadata,
201
+                                                     message_id)
195 202
             if not data['ipaotp']:
196 203
                 # OTP was not added to host, don't return one
197 204
                 del data['ipaotp']
@@ -199,24 +206,26 @@ class JoinController(Controller):
199 206
             LOG.error('adding host failed %s', e)
200 207
             LOG.error(traceback.format_exc())
201 208
 
202
-        self.ipaclient.start_batch_operation()
209
+        self.ipaclient.start_batch_operation(message_id)
203 210
         # key-per-service
204 211
         managed_services = [metadata[key] for key in metadata.keys()
205 212
                             if key.startswith('managed_service_')]
206 213
         if managed_services:
207
-            self.add_managed_services(data['hostname'], managed_services)
214
+            self.add_managed_services(
215
+                data['hostname'], managed_services, message_id)
208 216
 
209 217
         compact_services = util.get_compact_services(metadata)
210 218
         if compact_services:
211
-            self.add_compact_services(hostname_short, compact_services)
219
+            self.add_compact_services(
220
+                hostname_short, compact_services, message_id)
212 221
 
213
-        self.ipaclient.flush_batch_operation()
222
+        self.ipaclient.flush_batch_operation(message_id)
214 223
 
215 224
         return data
216 225
 
217
-    def add_managed_services(self, base_host, services):
226
+    def add_managed_services(self, base_host, services, message_id=0):
218 227
         """Make any host/principal assignments passed into metadata."""
219
-        LOG.debug("In add_managed_services")
228
+        LOG.debug("[%s] In add_managed_services", message_id)
220 229
 
221 230
         hosts_found = list()
222 231
         services_found = list()
@@ -226,17 +235,18 @@ class JoinController(Controller):
226 235
 
227 236
             # add host if not present
228 237
             if principal_host not in hosts_found:
229
-                self.ipaclient.add_subhost(principal_host)
238
+                self.ipaclient.add_subhost(principal_host, message_id)
230 239
                 hosts_found.append(principal_host)
231 240
 
232 241
             # add service if not present
233 242
             if principal not in services_found:
234
-                self.ipaclient.add_service(principal)
243
+                self.ipaclient.add_service(principal, message_id)
235 244
                 services_found.append(principal)
236 245
 
237
-            self.ipaclient.service_add_host(principal, base_host)
246
+            self.ipaclient.service_add_host(principal, base_host, message_id)
238 247
 
239
-    def add_compact_services(self, base_host_short, service_repr):
248
+    def add_compact_services(self, base_host_short, service_repr,
249
+                             message_id=0):
240 250
         """Make any host/principal assignments passed from metadata
241 251
 
242 252
         This takes a dictionary representation of the services and networks
@@ -270,7 +280,7 @@ class JoinController(Controller):
270 280
         This attempts to do a more compact representation since the nova
271 281
         metadta entries have a limit of 255 characters.
272 282
         """
273
-        LOG.debug("In add_compact_services")
283
+        LOG.debug("[%s] In add_compact_services", message_id)
274 284
 
275 285
         hosts_found = list()
276 286
         services_found = list()
@@ -284,12 +294,13 @@ class JoinController(Controller):
284 294
 
285 295
                 # add host if not present
286 296
                 if principal_host not in hosts_found:
287
-                    self.ipaclient.add_subhost(principal_host)
297
+                    self.ipaclient.add_subhost(principal_host, message_id)
288 298
                     hosts_found.append(principal_host)
289 299
 
290 300
                 # add service if not present
291 301
                 if principal not in services_found:
292
-                    self.ipaclient.add_service(principal)
302
+                    self.ipaclient.add_service(principal, message_id)
293 303
                     services_found.append(principal)
294 304
 
295
-                self.ipaclient.service_add_host(principal, base_host)
305
+                self.ipaclient.service_add_host(
306
+                    principal, base_host, message_id)

+ 63
- 49
novajoin/notifications.py View File

@@ -65,9 +65,10 @@ class Registry(dict):
65 65
     def __call__(self, name, version=None, service='nova'):
66 66
         def register_event(fun):
67 67
             if version:
68
-                def check_event(sself, payload):
68
+                def check_event(sself, payload, message_id):
69 69
                     self.check_version(payload, version, service)
70
-                    return fun(sself, payload[service + '_object.data'])
70
+                    return fun(sself, payload[service + '_object.data'],
71
+                               message_id)
71 72
                 self[name] = check_event
72 73
                 return check_event
73 74
             self[name] = fun
@@ -124,19 +125,22 @@ class NotificationEndpoint(object):
124 125
         LOG.debug("publisher: %s, event: %s, metadata: %s", publisher_id,
125 126
                   event_type, metadata)
126 127
 
128
+        message_id = metadata['message_id']
129
+
127 130
         event_handler = self.event_handlers.get(
128 131
             event_type, lambda payload: LOG.error("Status update or unknown"))
129 132
         # run event handler for received notification type
130
-        event_handler(self, payload)
133
+        event_handler(self, payload, message_id)
131 134
 
132 135
     @event_handlers('compute.instance.create.end')
133
-    def compute_instance_create(self, payload):
136
+    def compute_instance_create(self, payload, message_id):
134 137
         hostname = self._generate_hostname(payload.get('hostname'))
135 138
         instance_id = payload['instance_id']
136
-        LOG.info("Add new host %s (%s)", instance_id, hostname)
139
+        LOG.info("[%s] Add new host %s (%s)",
140
+                 message_id, instance_id, hostname)
137 141
 
138 142
     @event_handlers('compute.instance.update')
139
-    def compute_instance_update(self, payload):
143
+    def compute_instance_update(self, payload, message_id):
140 144
         ipa = ipaclient()
141 145
         join_controller = join.JoinController(ipa)
142 146
         hostname_short = payload['hostname']
@@ -149,33 +153,37 @@ class NotificationEndpoint(object):
149 153
         enroll = payload_metadata.get('ipa_enroll', '')
150 154
         image_enroll = image_metadata.get('ipa_enroll', '')
151 155
         if enroll.lower() != 'true' and image_enroll.lower() != 'true':
152
-            LOG.info('IPA enrollment not requested, skipping update of %s',
153
-                     hostname)
156
+            LOG.info(
157
+                '[%s] IPA enrollment not requested, skipping update of %s',
158
+                message_id, hostname)
154 159
             return
155 160
         # Ensure this instance exists in nova
156 161
         instance = get_instance(instance_id)
157 162
         if instance is None:
158
-            msg = 'No such instance-id, %s' % instance_id
163
+            msg = '[%s] No such instance-id, %s' % (message_id, instance_id)
159 164
             LOG.error(msg)
160 165
             return
161 166
 
162
-        ipa.start_batch_operation()
167
+        LOG.info("[%s] compute instance update for %s", message_id, hostname)
168
+
169
+        ipa.start_batch_operation(message_id)
163 170
         # key-per-service
164 171
         managed_services = [
165 172
             payload_metadata[key] for key in payload_metadata.keys()
166 173
             if key.startswith('managed_service_')]
167 174
         if managed_services:
168
-            join_controller.add_managed_services(hostname, managed_services)
175
+            join_controller.add_managed_services(
176
+                hostname, managed_services, message_id)
169 177
 
170 178
         compact_services = util.get_compact_services(payload_metadata)
171 179
         if compact_services:
172 180
             join_controller.add_compact_services(
173
-                hostname_short, compact_services)
181
+                hostname_short, compact_services, message_id)
174 182
 
175
-        ipa.flush_batch_operation()
183
+        ipa.flush_batch_operation(message_id)
176 184
 
177 185
     @event_handlers('compute.instance.delete.end')
178
-    def compute_instance_delete(self, payload):
186
+    def compute_instance_delete(self, payload, message_id):
179 187
         hostname_short = payload['hostname']
180 188
         instance_id = payload['instance_id']
181 189
         payload_metadata = payload['metadata']
@@ -187,49 +195,51 @@ class NotificationEndpoint(object):
187 195
         image_enroll = image_metadata.get('ipa_enroll', '')
188 196
 
189 197
         if enroll.lower() != 'true' and image_enroll.lower() != 'true':
190
-            LOG.info('IPA enrollment not requested, skipping delete of %s',
191
-                     hostname)
198
+            LOG.info(
199
+                '[%s] IPA enrollment not requested, skipping delete of %s',
200
+                message_id, hostname)
192 201
             return
193 202
 
194
-        LOG.info("Delete host %s (%s)", instance_id, hostname)
203
+        LOG.info("[%s] Delete host %s (%s)", message_id, instance_id, hostname)
195 204
         try:
196 205
             ipa = ipaclient()
197
-            ipa.delete_host(hostname, {})
206
+            ipa.delete_host(hostname, {}, message_id)
198 207
             self.delete_subhosts(ipa, hostname_short, payload_metadata)
199 208
         except exception.IPAConnectionError:
200
-            LOG.error("IPA Connection Error when deleting host %s (%s).  "
209
+            LOG.error("[%s] IPA Connection Error when deleting host %s (%s). "
201 210
                       "Manual cleanup may be required in the IPA server.",
202
-                      instance_id, hostname)
211
+                      message_id, instance_id, hostname)
203 212
 
204 213
     @event_handlers('network.floating_ip.associate')
205
-    def floaitng_ip_associate(self, payload):
214
+    def floaitng_ip_associate(self, payload, message_id):
206 215
         floating_ip = payload['floating_ip']
207
-        LOG.info("Associate floating IP %s" % floating_ip)
216
+        LOG.info("[%s] Associate floating IP %s" % (message_id, floating_ip))
208 217
         ipa = ipaclient()
209 218
         nova = novaclient()
210 219
         server = nova.servers.get(payload['instance_id'])
211 220
         if server:
212
-            ipa.add_ip(server.name, floating_ip)
221
+            ipa.add_ip(server.name, floating_ip, message_id)
213 222
         else:
214
-            LOG.error("Could not resolve %s into a hostname",
215
-                      payload['instance_id'])
223
+            LOG.error("[%s] Could not resolve %s into a hostname",
224
+                      message_id, payload['instance_id'])
216 225
 
217 226
     @event_handlers('network.floating_ip.disassociate')
218
-    def floating_ip_disassociate(self, payload):
227
+    def floating_ip_disassociate(self, payload, message_id):
219 228
         floating_ip = payload['floating_ip']
220
-        LOG.info("Disassociate floating IP %s" % floating_ip)
229
+        LOG.info("[%s] Disassociate floating IP %s", message_id, floating_ip)
221 230
         ipa = ipaclient()
222
-        ipa.remove_ip(floating_ip)
231
+        ipa.remove_ip(floating_ip, message_id)
223 232
 
224 233
     @event_handlers('floatingip.update.end')
225
-    def floating_ip_update(self, payload):
234
+    def floating_ip_update(self, payload, message_id):
226 235
         """Neutron event"""
227 236
         floatingip = payload['floatingip']
228 237
         floating_ip = floatingip['floating_ip_address']
229 238
         port_id = floatingip['port_id']
230 239
         ipa = ipaclient()
231 240
         if port_id:
232
-            LOG.info("Neutron floating IP associate: %s" % floating_ip)
241
+            LOG.info("[%s] Neutron floating IP associate: %s",
242
+                     message_id, floating_ip)
233 243
             nova = novaclient()
234 244
             neutron = neutronclient()
235 245
             search_opts = {'id': port_id}
@@ -239,14 +249,16 @@ class NotificationEndpoint(object):
239 249
                 if device_id:
240 250
                     server = nova.servers.get(device_id)
241 251
                     if server:
242
-                        ipa.add_ip(server.name, floating_ip)
252
+                        ipa.add_ip(server.name, floating_ip, message_id)
243 253
             else:
244
-                LOG.error("Expected 1 port, got %d", len(ports))
254
+                LOG.error("[%s] Expected 1 port, got %d",
255
+                          message_id, len(ports))
245 256
         else:
246
-            LOG.info("Neutron floating IP disassociate: %s" % floating_ip)
247
-            ipa.remove_ip(floating_ip)
257
+            LOG.info("[%s] Neutron floating IP disassociate: %s",
258
+                     message_id, floating_ip)
259
+            ipa.remove_ip(floating_ip, message_id)
248 260
 
249
-    def delete_subhosts(self, ipa, hostname_short, metadata):
261
+    def delete_subhosts(self, ipa, hostname_short, metadata, message_id):
250 262
         """Delete subhosts and remove VIPs if possible.
251 263
 
252 264
         Servers can have multiple network interfaces, and therefore can
@@ -269,13 +281,15 @@ class NotificationEndpoint(object):
269 281
         compact_services = util.get_compact_services(metadata)
270 282
         if compact_services:
271 283
             self.delete_compact_services(ipa, hostname_short,
272
-                                         compact_services)
284
+                                         compact_services,
285
+                                         message_id)
273 286
         managed_services = [metadata[key] for key in metadata.keys()
274 287
                             if key.startswith('managed_service_')]
275 288
         if managed_services:
276
-            self.delete_managed_services(ipa, managed_services)
289
+            self.delete_managed_services(ipa, managed_services, message_id)
277 290
 
278
-    def delete_compact_services(self, ipa, host_short, service_repr):
291
+    def delete_compact_services(self, ipa, host_short, service_repr,
292
+                                message_id):
279 293
         """Reconstructs and removes subhosts for compact services.
280 294
 
281 295
            Data looks like this:
@@ -289,10 +303,10 @@ class NotificationEndpoint(object):
289 303
             services to be automatically deleted through IPA referential
290 304
             integrity.
291 305
         """
292
-        LOG.debug("In delete compact services")
306
+        LOG.debug("[%s] In delete compact services", message_id)
293 307
         hosts_found = list()
294 308
 
295
-        ipa.start_batch_operation()
309
+        ipa.start_batch_operation(message_id)
296 310
         for service_name, net_list in service_repr.items():
297 311
             for network in net_list:
298 312
                 host = "%s.%s" % (host_short, network)
@@ -302,15 +316,15 @@ class NotificationEndpoint(object):
302 316
                 if principal_host not in hosts_found:
303 317
                     ipa.delete_subhost(principal_host)
304 318
                     hosts_found.append(principal_host)
305
-        ipa.flush_batch_operation()
319
+        ipa.flush_batch_operation(message_id)
306 320
 
307
-    def delete_managed_services(self, ipa, services):
321
+    def delete_managed_services(self, ipa, services, message_id):
308 322
         """Delete any managed services if possible.
309 323
 
310 324
            Checks to see if the managed service subhost has no managed hosts
311 325
            associations and if so, deletes the host.
312 326
         """
313
-        LOG.debug("In delete_managed_services")
327
+        LOG.debug("[%s] In delete_managed_services", message_id)
314 328
         hosts_deleted = list()
315 329
         services_deleted = list()
316 330
 
@@ -353,15 +367,15 @@ class VersionedNotificationEndpoint(NotificationEndpoint):
353 367
     event_handlers = Registry(NotificationEndpoint.event_handlers)
354 368
 
355 369
     @event_handlers('instance.create.end', '1.10')
356
-    def instance_create(self, payload):
370
+    def instance_create(self, payload, message_id):
357 371
         newpayload = {
358 372
             'hostname': payload['host_name'],
359 373
             'instance_id': payload['uuid'],
360 374
         }
361
-        self.compute_instance_create(newpayload)
375
+        self.compute_instance_create(newpayload, message_id)
362 376
 
363 377
     @event_handlers('instance.update', '1.8')
364
-    def instance_update(self, payload):
378
+    def instance_update(self, payload, message_id):
365 379
         glance = glanceclient()
366 380
         newpayload = {
367 381
             'hostname': payload['host_name'],
@@ -369,10 +383,10 @@ class VersionedNotificationEndpoint(NotificationEndpoint):
369 383
             'metadata': payload['metadata'],
370 384
             'image_meta': glance.images.get(payload['image_uuid'])
371 385
         }
372
-        self.compute_instance_update(newpayload)
386
+        self.compute_instance_update(newpayload, message_id)
373 387
 
374 388
     @event_handlers('instance.delete.end', '1.7')
375
-    def instance_delete(self, payload):
389
+    def instance_delete(self, payload, message_id):
376 390
         glance = glanceclient()
377 391
         newpayload = {
378 392
             'hostname': payload['host_name'],
@@ -380,7 +394,7 @@ class VersionedNotificationEndpoint(NotificationEndpoint):
380 394
             'metadata': payload['metadata'],
381 395
             'image_meta': glance.images.get(payload['image_uuid'])
382 396
         }
383
-        self.compute_instance_delete(newpayload)
397
+        self.compute_instance_delete(newpayload, message_id)
384 398
 
385 399
 
386 400
 def main():

Loading…
Cancel
Save