1362899 - Autophone - lock released too many times while shutting down pulse listener

Status: RESOLVED FIXED

(Testing Graveyard :: Autophone, defect)

Description

[Bob Clary [:bc] (inactive)]

During testing I ran into the following after a restart followed some time later by a shutdown

2017-05-07 16:54:50,627 console INFO Autophone started.
Exception in thread PulseMonitorThread:
Traceback (most recent call last):
  File "/usr/lib64/python2.7/threading.py", line 804, in __bootstrap_inner
    self.run()
  File "/usr/lib64/python2.7/threading.py", line 757, in run
    self.__target(*self.__args, **self.__kwargs)
  File "/mozilla/projects/autophone/src/bclary-autophone/autophonepulsemonitor.py", line 258, in listen
    self.shared_lock.release()
ValueError: semaphore or lock released too many times

this occurs in the finally clause as the listen method is exited.

Comment 1

[Bob Clary [:bc] (inactive)]

This was caused by an exception cause by code under development in the handle_build method

Traceback (most recent call last):
  File "/mozilla/projects/autophone/src/bclary-autophone/autophonepulsemonitor.py", line 232, in listen
    connection.drain_events(timeout=self.timeout)
  File "/mozilla/projects/.virtualenvs/autophone/lib/python2.7/site-packages/kombu/connection.py", line 301, in drain_events
    return self.transport.drain_events(self.connection, **kwargs)
  File "/mozilla/projects/.virtualenvs/autophone/lib/python2.7/site-packages/kombu/transport/pyamqp.py", line 103, in drain_events
    return connection.drain_events(**kwargs)
  File "/mozilla/projects/.virtualenvs/autophone/lib/python2.7/site-packages/amqp/connection.py", line 464, in drain_events
    return self.blocking_read(timeout)
  File "/mozilla/projects/.virtualenvs/autophone/lib/python2.7/site-packages/amqp/connection.py", line 469, in blocking_read
    return self.on_inbound_frame(frame)
  File "/mozilla/projects/.virtualenvs/autophone/lib/python2.7/site-packages/amqp/method_framing.py", line 88, in on_frame
    callback(channel, msg.frame_method, msg.frame_args, msg)
  File "/mozilla/projects/.virtualenvs/autophone/lib/python2.7/site-packages/amqp/connection.py", line 473, in on_inbound_method
    method_sig, payload, content,
  File "/mozilla/projects/.virtualenvs/autophone/lib/python2.7/site-packages/amqp/abstract_channel.py", line 142, in dispatch_method
    listener(*args)
  File "/mozilla/projects/.virtualenvs/autophone/lib/python2.7/site-packages/amqp/channel.py", line 1613, in _on_basic_deliver
    fun(msg)
  File "/mozilla/projects/.virtualenvs/autophone/lib/python2.7/site-packages/kombu/messaging.py", line 623, in _receive_callback
    return on_m(message) if on_m else self.receive(decoded, message)
  File "/mozilla/projects/.virtualenvs/autophone/lib/python2.7/site-packages/kombu/messaging.py", line 589, in receive
    [callback(body, message) for callback in callbacks]
  File "/mozilla/projects/autophone/src/bclary-autophone/autophonepulsemonitor.py", line 275, in handle_message
    self.handle_build(data, message)
  File "/mozilla/projects/autophone/src/bclary-autophone/autophonepulsemonitor.py", line 339, in handle_build
    build_properties['appname'].lower() != 'geckoviewactivity':
KeyError: 'appname'

This may be invalid though it does seem to me that the lock should have been reacquired before the outer finally clause.

Comment 2

[Bob Clary [:bc] (inactive)]

Attachment: bug-1362899-LOGGER.patch

At least part of the problem and maybe the full problem was the failure to change all instances of LOGGER to logger in 1304063 which raised an exception prior to the reacquiring of the shared lock. This only shows up when verbose logging is enabled which isn't the case in production fortunately.

Comment 3

[Joel Maher ( :jmaher ) (UTC -8)]

Comment on attachment 8865415 [details] [diff] [review]
bug-1362899-LOGGER.patch

Review of attachment 8865415 [details] [diff] [review]:
-----------------------------------------------------------------

easy one!

Comment 4

[Bob Clary [:bc] (inactive)]

https://github.com/mozilla/autophone/commit/c3e4974014cd6a928baf6614306a73a807917f52