Merge lp:~robru/friends/refresh-fixup into lp:friends
- refresh-fixup
- Merge into trunk
Status: | Merged |
---|---|
Merge reported by: | Robert Bruce Park |
Merged at revision: | not available |
Proposed branch: | lp:~robru/friends/refresh-fixup |
Merge into: | lp:friends |
Diff against target: |
833 lines (+160/-139) 24 files modified
friends-service.sh (+1/-1) friends/main.py (+4/-2) friends/protocols/facebook.py (+1/-1) friends/protocols/flickr.py (+1/-1) friends/protocols/foursquare.py (+1/-1) friends/protocols/twitter.py (+6/-7) friends/service/connection.py (+1/-1) friends/service/dispatcher.py (+2/-1) friends/service/shortener.py (+1/-1) friends/testing/mocks.py (+3/-3) friends/testing/service.py (+1/-1) friends/tests/test_authentication.py (+15/-9) friends/tests/test_download.py (+14/-8) friends/tests/test_facebook.py (+2/-0) friends/tests/test_flickr.py (+16/-2) friends/tests/test_logging.py (+16/-37) friends/utils/account.py (+1/-1) friends/utils/authentication.py (+15/-15) friends/utils/avatar.py (+1/-1) friends/utils/base.py (+8/-3) friends/utils/download.py (+4/-11) friends/utils/logging.py (+24/-11) friends/utils/menus.py (+1/-1) tools/debug_live.py (+21/-20) |
To merge this branch: | bzr merge lp:~robru/friends/refresh-fixup |
Related bugs: |
Reviewer | Review Type | Date Requested | Status |
---|---|---|---|
Robert Bruce Park | Approve | ||
Review via email: mp+130456@code.launchpad.net |
Commit message
Workaround for Authentication.
I've replaced this mainloop with a while loop that calls time.sleep() a limited number of times. The advantage here is that we have direct control over how many times time.sleep() gets called and never have to worry about waiting for a callback that might never come to unblock us.
This commit also makes sweeping changes to the logging infrastructure, which were necessary to track down this bug, and generally beneficial, so they're being included rather than reverted. Logging is now more verbose, and makes extensive use of the "logging.
Description of the change
This branch fixes one of the major causes of dispatcher.Refresh hanging, in particular with Authentication.
I'm afraid there may be more conditions in which dispatcher.Refresh will hang, but they've been much more intermittent and difficult to pinpoint thus far. But this should still be merged as-is because it's an important fix to a really stupid part of old gwibber code that somehow managed to survive into the friends-service transition.
Robert Bruce Park (robru) wrote : | # |
- 14. By Robert Bruce Park
-
Drop extraneous instance attribute from Authentication class.
This commit also does some minor cleanups, and introduces some new
debugging statements that may prove helpful in tracking down any
future hangs we discover.Authentication.
_authenticating turned out to be redundant, I've
dropped it in favor of testing for the presence of self._reply
directly. Authentication.login sees that self._reply isn't populated
yet, so it blocks, and then the callback populates that value and
stops the lock, allowing login() to return that value.
Robert Bruce Park (robru) wrote : | # |
Ken, I've added a couple log.debug statements at the beginning and ending of our Thread.run subclass, so that now it should be really obvious to us in the debugging output when threads are starting and stopping. I still can no longer reproduce any more hangs in dispatcher.Refresh, I've let it run for quite a while with many iterations and no issues.
Please merge and then we'll just have to keep an eye out for any hangs if they return in the future.
- 15. By Robert Bruce Park
-
Set self._reply sooner, and unconditionally.
- 16. By Robert Bruce Park
-
Test suite fixups ;-)
- 17. By Robert Bruce Park
-
Replace threading.Lock() with time.sleep()
Yes, yes, I know time.sleep() is ugly, but this is looking like the
only way I can get this working quite right. The previous attempts
using threading.Lock and GObject.MainLoops both had very subtle hangs
that basically screwed up everything. - 18. By Robert Bruce Park
-
Make logging *much* more explicit about what is being logged from where.
- 19. By Robert Bruce Park
-
Overhaul debug_live.py to make it compatible with Authentication changes.
- 20. By Robert Bruce Park
-
Update tests to no longer expect HTTPError to be raised.
This brings us much more into line with the Soup way of doing things,
rather than trying to force urllib-like behavior on top of Soup. - 21. By Robert Bruce Park
-
Resurrect logging from friends-service.sh
- 22. By Robert Bruce Park
-
Overhaul a lot of the logging logic.
Logging now works in both friends-service and in debug_live. I found a
workaround for that duplicate-records bug. Tests have been updated. - 23. By Robert Bruce Park
-
Fix the last of the test failures.
- 24. By Robert Bruce Park
-
Greatly simplify the logging logic. Was overthinking it before...
- 25. By Robert Bruce Park
-
Simplify debug_live.py
- 26. By Robert Bruce Park
-
debug_live.py doesn't need to be on a loop anymore.
The looping of it was primarily useful before we had the dispatcher
actually running. Now that we have the dispatcher, debug_live is more
just for firing single messages.
Robert Bruce Park (robru) wrote : | # |
All tests pass, friends-service ran all overnight with no hangs, all good!
Preview Diff
1 | === modified file 'friends-service.sh' | |||
2 | --- friends-service.sh 2012-10-18 17:48:42 +0000 | |||
3 | +++ friends-service.sh 2012-10-20 00:36:21 +0000 | |||
4 | @@ -1,3 +1,3 @@ | |||
5 | 1 | #! /bin/sh | 1 | #! /bin/sh |
6 | 2 | 2 | ||
8 | 3 | PYTHONPATH=. python3 -m friends.main -do | 3 | PYTHONPATH=. python3 -m friends.main --debug --console |
9 | 4 | 4 | ||
10 | === modified file 'friends/main.py' | |||
11 | --- friends/main.py 2012-10-15 18:56:26 +0000 | |||
12 | +++ friends/main.py 2012-10-20 00:36:21 +0000 | |||
13 | @@ -26,7 +26,9 @@ | |||
14 | 26 | import logging | 26 | import logging |
15 | 27 | 27 | ||
16 | 28 | from dbus.mainloop.glib import DBusGMainLoop | 28 | from dbus.mainloop.glib import DBusGMainLoop |
18 | 29 | from gi.repository import Gio, GLib | 29 | from gi.repository import Gio, GLib, GObject |
19 | 30 | |||
20 | 31 | GObject.threads_init(None) | ||
21 | 30 | 32 | ||
22 | 31 | from friends.service.connection import ConnectionMonitor | 33 | from friends.service.connection import ConnectionMonitor |
23 | 32 | from friends.service.dispatcher import Dispatcher | 34 | from friends.service.dispatcher import Dispatcher |
24 | @@ -56,7 +58,7 @@ | |||
25 | 56 | gsettings = Gio.Settings.new('org.gwibber.preferences') | 58 | gsettings = Gio.Settings.new('org.gwibber.preferences') |
26 | 57 | initialize(console=args.console, | 59 | initialize(console=args.console, |
27 | 58 | debug=args.debug or gsettings.get_boolean('debug')) | 60 | debug=args.debug or gsettings.get_boolean('debug')) |
29 | 59 | log = logging.getLogger('friends.service') | 61 | log = logging.getLogger(__name__) |
30 | 60 | log.info('Friends backend service starting') | 62 | log.info('Friends backend service starting') |
31 | 61 | 63 | ||
32 | 62 | # Set up the DBus main loop. | 64 | # Set up the DBus main loop. |
33 | 63 | 65 | ||
34 | === modified file 'friends/protocols/facebook.py' | |||
35 | --- friends/protocols/facebook.py 2012-10-16 04:10:50 +0000 | |||
36 | +++ friends/protocols/facebook.py 2012-10-20 00:36:21 +0000 | |||
37 | @@ -37,7 +37,7 @@ | |||
38 | 37 | ME_URL = API_BASE.format(id='me') | 37 | ME_URL = API_BASE.format(id='me') |
39 | 38 | 38 | ||
40 | 39 | 39 | ||
42 | 40 | log = logging.getLogger('friends.service') | 40 | log = logging.getLogger(__name__) |
43 | 41 | 41 | ||
44 | 42 | 42 | ||
45 | 43 | class Facebook(Base): | 43 | class Facebook(Base): |
46 | 44 | 44 | ||
47 | === modified file 'friends/protocols/flickr.py' | |||
48 | --- friends/protocols/flickr.py 2012-10-13 01:27:15 +0000 | |||
49 | +++ friends/protocols/flickr.py 2012-10-20 00:36:21 +0000 | |||
50 | @@ -28,7 +28,7 @@ | |||
51 | 28 | from friends.utils.time import iso8601utc, parsetime | 28 | from friends.utils.time import iso8601utc, parsetime |
52 | 29 | 29 | ||
53 | 30 | 30 | ||
55 | 31 | log = logging.getLogger('friends.service') | 31 | log = logging.getLogger(__name__) |
56 | 32 | 32 | ||
57 | 33 | 33 | ||
58 | 34 | # This is contact information for the Flickr REST service. | 34 | # This is contact information for the Flickr REST service. |
59 | 35 | 35 | ||
60 | === modified file 'friends/protocols/foursquare.py' | |||
61 | --- friends/protocols/foursquare.py 2012-10-13 01:27:15 +0000 | |||
62 | +++ friends/protocols/foursquare.py 2012-10-20 00:36:21 +0000 | |||
63 | @@ -28,7 +28,7 @@ | |||
64 | 28 | from friends.utils.time import iso8601utc | 28 | from friends.utils.time import iso8601utc |
65 | 29 | 29 | ||
66 | 30 | 30 | ||
68 | 31 | log = logging.getLogger('friends.service') | 31 | log = logging.getLogger(__name__) |
69 | 32 | 32 | ||
70 | 33 | 33 | ||
71 | 34 | # The '&v=YYYYMMDD' defines the date that the API was last confirmed to be | 34 | # The '&v=YYYYMMDD' defines the date that the API was last confirmed to be |
72 | 35 | 35 | ||
73 | === modified file 'friends/protocols/twitter.py' | |||
74 | --- friends/protocols/twitter.py 2012-10-16 04:10:50 +0000 | |||
75 | +++ friends/protocols/twitter.py 2012-10-20 00:36:21 +0000 | |||
76 | @@ -34,17 +34,16 @@ | |||
77 | 34 | from friends.utils.time import parsetime, iso8601utc | 34 | from friends.utils.time import parsetime, iso8601utc |
78 | 35 | 35 | ||
79 | 36 | 36 | ||
81 | 37 | log = logging.getLogger('friends.service') | 37 | log = logging.getLogger(__name__) |
82 | 38 | 38 | ||
83 | 39 | 39 | ||
84 | 40 | # https://dev.twitter.com/docs/api/1.1 | 40 | # https://dev.twitter.com/docs/api/1.1 |
85 | 41 | class Twitter(Base): | 41 | class Twitter(Base): |
92 | 42 | # StatusNet claims to mimick the Twitter API very closely (so closely to | 42 | # Identi.ca's API mimicks Twitter's to such a high degree that it |
93 | 43 | # the point that they refer you to the Twitter API reference docs as a | 43 | # is implemented just as a subclass of this, hence we need these |
94 | 44 | # starting point for learning about their API). So these prefixes are | 44 | # constants defined as instance attributes, so that the Identica |
95 | 45 | # defined here as class attributes instead of the usual module globals, in | 45 | # class can override them. If you make any changes to this class |
96 | 46 | # the hopes that the StatusNet class will be able to subclass Twitter and | 46 | # you must confirm that your changes do not break Identi.ca! |
91 | 47 | # change only the URLs, with minimal other changes, and magically work. | ||
97 | 48 | _api_base = 'https://api.twitter.com/1.1/{endpoint}.json' | 47 | _api_base = 'https://api.twitter.com/1.1/{endpoint}.json' |
98 | 49 | 48 | ||
99 | 50 | _timeline = _api_base.format(endpoint='statuses/{}_timeline') | 49 | _timeline = _api_base.format(endpoint='statuses/{}_timeline') |
100 | 51 | 50 | ||
101 | === modified file 'friends/service/connection.py' | |||
102 | --- friends/service/connection.py 2012-10-13 01:27:15 +0000 | |||
103 | +++ friends/service/connection.py 2012-10-20 00:36:21 +0000 | |||
104 | @@ -50,7 +50,7 @@ | |||
105 | 50 | DISCONNECTED = 4 | 50 | DISCONNECTED = 4 |
106 | 51 | 51 | ||
107 | 52 | 52 | ||
109 | 53 | log = logging.getLogger('friends.service') | 53 | log = logging.getLogger(__name__) |
110 | 54 | _State = None | 54 | _State = None |
111 | 55 | 55 | ||
112 | 56 | 56 | ||
113 | 57 | 57 | ||
114 | === modified file 'friends/service/dispatcher.py' | |||
115 | --- friends/service/dispatcher.py 2012-10-13 01:27:15 +0000 | |||
116 | +++ friends/service/dispatcher.py 2012-10-20 00:36:21 +0000 | |||
117 | @@ -34,7 +34,7 @@ | |||
118 | 34 | from friends.utils.manager import protocol_manager | 34 | from friends.utils.manager import protocol_manager |
119 | 35 | from friends.utils.signaler import signaler | 35 | from friends.utils.signaler import signaler |
120 | 36 | 36 | ||
122 | 37 | log = logging.getLogger('friends.service') | 37 | log = logging.getLogger(__name__) |
123 | 38 | 38 | ||
124 | 39 | 39 | ||
125 | 40 | class Dispatcher(dbus.service.Object): | 40 | class Dispatcher(dbus.service.Object): |
126 | @@ -53,6 +53,7 @@ | |||
127 | 53 | signaler.add_signal('ConnectionOnline', self._on_connection_online) | 53 | signaler.add_signal('ConnectionOnline', self._on_connection_online) |
128 | 54 | signaler.add_signal('ConnectionOffline', self._on_connection_offline) | 54 | signaler.add_signal('ConnectionOffline', self._on_connection_offline) |
129 | 55 | self._on_connection_online() | 55 | self._on_connection_online() |
130 | 56 | self.Refresh() | ||
131 | 56 | 57 | ||
132 | 57 | def _on_connection_online(self): | 58 | def _on_connection_online(self): |
133 | 58 | if not self._timer_id: | 59 | if not self._timer_id: |
134 | 59 | 60 | ||
135 | === modified file 'friends/service/shortener.py' | |||
136 | --- friends/service/shortener.py 2012-10-13 01:27:15 +0000 | |||
137 | +++ friends/service/shortener.py 2012-10-20 00:36:21 +0000 | |||
138 | @@ -27,7 +27,7 @@ | |||
139 | 27 | 27 | ||
140 | 28 | from friends.shorteners import lookup | 28 | from friends.shorteners import lookup |
141 | 29 | 29 | ||
143 | 30 | log = logging.getLogger('friends.service') | 30 | log = logging.getLogger(__name__) |
144 | 31 | 31 | ||
145 | 32 | 32 | ||
146 | 33 | class URLShorten(dbus.service.Object): | 33 | class URLShorten(dbus.service.Object): |
147 | 34 | 34 | ||
148 | === modified file 'friends/testing/mocks.py' | |||
149 | --- friends/testing/mocks.py 2012-10-17 18:55:49 +0000 | |||
150 | +++ friends/testing/mocks.py 2012-10-20 00:36:21 +0000 | |||
151 | @@ -168,7 +168,7 @@ | |||
152 | 168 | """ | 168 | """ |
153 | 169 | def __init__(self, *modules): | 169 | def __init__(self, *modules): |
154 | 170 | self._queue = Queue() | 170 | self._queue = Queue() |
156 | 171 | self._log = logging.getLogger('friends.test') | 171 | self._log = logging.getLogger(__name__) |
157 | 172 | handler = QueueHandler(self._queue) | 172 | handler = QueueHandler(self._queue) |
158 | 173 | formatter = logging.Formatter(LOG_FORMAT, style='{') | 173 | formatter = logging.Formatter(LOG_FORMAT, style='{') |
159 | 174 | handler.setFormatter(formatter) | 174 | handler.setFormatter(formatter) |
160 | @@ -205,8 +205,8 @@ | |||
161 | 205 | self.empty() | 205 | self.empty() |
162 | 206 | for patcher in self._patchers: | 206 | for patcher in self._patchers: |
163 | 207 | patcher.stop() | 207 | patcher.stop() |
166 | 208 | # Get rid of the friends.test logger. | 208 | # Get rid of the mock logger. |
167 | 209 | del logging.Logger.manager.loggerDict['friends.test'] | 209 | del logging.Logger.manager.loggerDict[__name__] |
168 | 210 | 210 | ||
169 | 211 | def empty(self, trim=True): | 211 | def empty(self, trim=True): |
170 | 212 | """Return all the log messages written to this log. | 212 | """Return all the log messages written to this log. |
171 | 213 | 213 | ||
172 | === modified file 'friends/testing/service.py' | |||
173 | --- friends/testing/service.py 2012-10-13 01:27:15 +0000 | |||
174 | +++ friends/testing/service.py 2012-10-20 00:36:21 +0000 | |||
175 | @@ -28,7 +28,7 @@ | |||
176 | 28 | from friends.utils.signaler import signaler | 28 | from friends.utils.signaler import signaler |
177 | 29 | 29 | ||
178 | 30 | 30 | ||
180 | 31 | log = logging.getLogger('friends.service') | 31 | log = logging.getLogger(__name__) |
181 | 32 | 32 | ||
182 | 33 | 33 | ||
183 | 34 | class TestService(dbus.service.Object): | 34 | class TestService(dbus.service.Object): |
184 | 35 | 35 | ||
185 | === modified file 'friends/tests/test_authentication.py' | |||
186 | --- friends/tests/test_authentication.py 2012-10-13 01:27:15 +0000 | |||
187 | +++ friends/tests/test_authentication.py 2012-10-20 00:36:21 +0000 | |||
188 | @@ -62,6 +62,11 @@ | |||
189 | 62 | def error(self, message, *args): | 62 | def error(self, message, *args): |
190 | 63 | self.error_messages.append(message.format(*args)) | 63 | self.error_messages.append(message.format(*args)) |
191 | 64 | 64 | ||
192 | 65 | reset = __init__ | ||
193 | 66 | |||
194 | 67 | |||
195 | 68 | logger = Logger() | ||
196 | 69 | |||
197 | 65 | 70 | ||
198 | 66 | class TestAuthentication(unittest.TestCase): | 71 | class TestAuthentication(unittest.TestCase): |
199 | 67 | """Test authentication.""" | 72 | """Test authentication.""" |
200 | @@ -72,28 +77,29 @@ | |||
201 | 72 | self.account.auth.method = 'some method' | 77 | self.account.auth.method = 'some method' |
202 | 73 | self.account.auth.parameters = 'change me' | 78 | self.account.auth.parameters = 'change me' |
203 | 74 | self.account.auth.mechanism = ['whatever'] | 79 | self.account.auth.mechanism = ['whatever'] |
205 | 75 | self.logger = Logger() | 80 | logger.reset() |
206 | 76 | 81 | ||
207 | 82 | @mock.patch('friends.utils.authentication.log', logger) | ||
208 | 77 | @mock.patch('friends.utils.authentication.Signon', FakeSignon) | 83 | @mock.patch('friends.utils.authentication.Signon', FakeSignon) |
209 | 78 | def test_successful_login(self): | 84 | def test_successful_login(self): |
210 | 79 | # Prevent an error in the callback. | 85 | # Prevent an error in the callback. |
211 | 80 | self.account.auth.parameters = False | 86 | self.account.auth.parameters = False |
213 | 81 | authenticator = Authentication(self.account, self.logger) | 87 | authenticator = Authentication(self.account) |
214 | 82 | reply = authenticator.login() | 88 | reply = authenticator.login() |
215 | 83 | self.assertEqual(reply, 'auth reply') | 89 | self.assertEqual(reply, 'auth reply') |
219 | 84 | self.assertEqual(self.logger.debug_messages, | 90 | self.assertEqual(logger.debug_messages, ['Login completed']) |
220 | 85 | ['Login completed']) | 91 | self.assertEqual(logger.error_messages, []) |
218 | 86 | self.assertEqual(self.logger.error_messages, []) | ||
221 | 87 | 92 | ||
222 | 93 | @mock.patch('friends.utils.authentication.log', logger) | ||
223 | 88 | @mock.patch('friends.utils.authentication.Signon', FakeSignon) | 94 | @mock.patch('friends.utils.authentication.Signon', FakeSignon) |
224 | 89 | def test_failed_login(self): | 95 | def test_failed_login(self): |
225 | 90 | # Trigger an error in the callback. | 96 | # Trigger an error in the callback. |
226 | 91 | class Error: | 97 | class Error: |
227 | 92 | message = 'who are you?' | 98 | message = 'who are you?' |
228 | 93 | self.account.auth.parameters = Error | 99 | self.account.auth.parameters = Error |
230 | 94 | authenticator = Authentication(self.account, self.logger) | 100 | authenticator = Authentication(self.account) |
231 | 95 | reply = authenticator.login() | 101 | reply = authenticator.login() |
235 | 96 | self.assertIsNone(reply) | 102 | self.assertEqual(reply, 'auth reply') |
236 | 97 | self.assertEqual(self.logger.debug_messages, ['Login completed']) | 103 | self.assertEqual(logger.debug_messages, ['Login completed']) |
237 | 98 | self.assertEqual(self.logger.error_messages, | 104 | self.assertEqual(logger.error_messages, |
238 | 99 | ['Got authentication error: who are you?']) | 105 | ['Got authentication error: who are you?']) |
239 | 100 | 106 | ||
240 | === modified file 'friends/tests/test_download.py' | |||
241 | --- friends/tests/test_download.py 2012-10-13 01:27:15 +0000 | |||
242 | +++ friends/tests/test_download.py 2012-10-20 00:36:21 +0000 | |||
243 | @@ -33,7 +33,7 @@ | |||
244 | 33 | from wsgiref.simple_server import WSGIRequestHandler, make_server | 33 | from wsgiref.simple_server import WSGIRequestHandler, make_server |
245 | 34 | from wsgiref.util import setup_testing_defaults | 34 | from wsgiref.util import setup_testing_defaults |
246 | 35 | 35 | ||
248 | 36 | from friends.testing.mocks import FakeSoupMessage | 36 | from friends.testing.mocks import FakeSoupMessage, LogMock |
249 | 37 | from friends.utils.download import Downloader, get_json | 37 | from friends.utils.download import Downloader, get_json |
250 | 38 | 38 | ||
251 | 39 | try: | 39 | try: |
252 | @@ -123,6 +123,12 @@ | |||
253 | 123 | class TestDownloader(unittest.TestCase): | 123 | class TestDownloader(unittest.TestCase): |
254 | 124 | """Test the downloading utilities.""" | 124 | """Test the downloading utilities.""" |
255 | 125 | 125 | ||
256 | 126 | def setUp(self): | ||
257 | 127 | self.log_mock = LogMock('friends.utils.download') | ||
258 | 128 | |||
259 | 129 | def tearDown(self): | ||
260 | 130 | self.log_mock.stop() | ||
261 | 131 | |||
262 | 126 | @classmethod | 132 | @classmethod |
263 | 127 | def setUpClass(cls): | 133 | def setUpClass(cls): |
264 | 128 | cls.server = make_server('', 9180, _app, handler_class=_SilentHandler) | 134 | cls.server = make_server('', 9180, _app, handler_class=_SilentHandler) |
265 | @@ -231,17 +237,17 @@ | |||
266 | 231 | 237 | ||
267 | 232 | def test_unauthorized(self): | 238 | def test_unauthorized(self): |
268 | 233 | # Test a URL that requires authorization. | 239 | # Test a URL that requires authorization. |
272 | 234 | with self.assertRaises(HTTPError) as cm: | 240 | Downloader('http://localhost:9180/auth').get_string() |
273 | 235 | Downloader('http://localhost:9180/auth').get_string() | 241 | self.assertEqual(self.log_mock.empty(), |
274 | 236 | self.assertEqual(cm.exception.code, 401) | 242 | 'http://localhost:9180/auth: 401 Unauthorized\n') |
275 | 237 | 243 | ||
276 | 238 | def test_bad_authorization(self): | 244 | def test_bad_authorization(self): |
277 | 239 | # Test a URL that requires authorization, but doesn't have the correct | 245 | # Test a URL that requires authorization, but doesn't have the correct |
278 | 240 | # username or password. | 246 | # username or password. |
283 | 241 | with self.assertRaises(HTTPError) as cm: | 247 | Downloader('http://localhost:9180/auth', |
284 | 242 | Downloader('http://localhost:9180/auth', | 248 | username='bob', password='wrong').get_string() |
285 | 243 | username='bob', password='wrong').get_string() | 249 | self.assertEqual(self.log_mock.empty(), |
286 | 244 | self.assertEqual(cm.exception.code, 401) | 250 | 'http://localhost:9180/auth: 401 Unauthorized\n') |
287 | 245 | 251 | ||
288 | 246 | def test_authorized(self): | 252 | def test_authorized(self): |
289 | 247 | # Test a URL that requires authorization, and has the proper | 253 | # Test a URL that requires authorization, and has the proper |
290 | 248 | 254 | ||
291 | === modified file 'friends/tests/test_facebook.py' | |||
292 | --- friends/tests/test_facebook.py 2012-10-17 18:55:49 +0000 | |||
293 | +++ friends/tests/test_facebook.py 2012-10-20 00:36:21 +0000 | |||
294 | @@ -102,9 +102,11 @@ | |||
295 | 102 | self.protocol('receive') | 102 | self.protocol('receive') |
296 | 103 | contents = log_mock.empty(trim=False) | 103 | contents = log_mock.empty(trim=False) |
297 | 104 | self.assertEqual(contents, """\ | 104 | self.assertEqual(contents, """\ |
298 | 105 | Facebook.receive is starting in a new thread. | ||
299 | 105 | Logging in to Facebook | 106 | Logging in to Facebook |
300 | 106 | Facebook UID: None | 107 | Facebook UID: None |
301 | 107 | Facebook error (190 OAuthException): Bad access token | 108 | Facebook error (190 OAuthException): Bad access token |
302 | 109 | Facebook.receive has completed, thread exiting. | ||
303 | 108 | """) | 110 | """) |
304 | 109 | 111 | ||
305 | 110 | @mock.patch('friends.utils.download.Soup.Message', | 112 | @mock.patch('friends.utils.download.Soup.Message', |
306 | 111 | 113 | ||
307 | === modified file 'friends/tests/test_flickr.py' | |||
308 | --- friends/tests/test_flickr.py 2012-10-17 18:55:49 +0000 | |||
309 | +++ friends/tests/test_flickr.py 2012-10-20 00:36:21 +0000 | |||
310 | @@ -71,12 +71,14 @@ | |||
311 | 71 | with mock.patch.object(self.protocol, '_get_nsid', return_value=None): | 71 | with mock.patch.object(self.protocol, '_get_nsid', return_value=None): |
312 | 72 | self.protocol('receive') | 72 | self.protocol('receive') |
313 | 73 | self.assertEqual(self.log_mock.empty(), """\ | 73 | self.assertEqual(self.log_mock.empty(), """\ |
314 | 74 | Flickr.receive is starting in a new thread. | ||
315 | 74 | Flickr: No NSID available | 75 | Flickr: No NSID available |
316 | 75 | Friends operation exception: | 76 | Friends operation exception: |
317 | 76 | Traceback (most recent call last): | 77 | Traceback (most recent call last): |
318 | 77 | ... | 78 | ... |
319 | 78 | friends.errors.AuthorizationError:\ | 79 | friends.errors.AuthorizationError:\ |
320 | 79 | No Flickr user id available (account: faker/than fake) | 80 | No Flickr user id available (account: faker/than fake) |
321 | 81 | Flickr.receive has completed, thread exiting. | ||
322 | 80 | """) | 82 | """) |
323 | 81 | 83 | ||
324 | 82 | @mock.patch('friends.utils.download.Soup.Message', | 84 | @mock.patch('friends.utils.download.Soup.Message', |
325 | @@ -90,7 +92,10 @@ | |||
326 | 90 | # AuthorizationError. | 92 | # AuthorizationError. |
327 | 91 | self.protocol('receive') | 93 | self.protocol('receive') |
328 | 92 | # No error messages. | 94 | # No error messages. |
330 | 93 | self.assertEqual(self.log_mock.empty(), '') | 95 | self.assertEqual(self.log_mock.empty(), """\ |
331 | 96 | Flickr.receive is starting in a new thread. | ||
332 | 97 | Flickr.receive has completed, thread exiting. | ||
333 | 98 | """) | ||
334 | 94 | # But also no photos. | 99 | # But also no photos. |
335 | 95 | self.assertEqual(TestModel.get_n_rows(), 0) | 100 | self.assertEqual(TestModel.get_n_rows(), 0) |
336 | 96 | 101 | ||
337 | @@ -108,11 +113,13 @@ | |||
338 | 108 | side_effect=side_effect): | 113 | side_effect=side_effect): |
339 | 109 | self.protocol('receive') | 114 | self.protocol('receive') |
340 | 110 | self.assertEqual(self.log_mock.empty(), """\ | 115 | self.assertEqual(self.log_mock.empty(), """\ |
341 | 116 | Flickr.receive is starting in a new thread. | ||
342 | 111 | Friends operation exception: | 117 | Friends operation exception: |
343 | 112 | Traceback (most recent call last): | 118 | Traceback (most recent call last): |
344 | 113 | ... | 119 | ... |
345 | 114 | friends.errors.AuthorizationError:\ | 120 | friends.errors.AuthorizationError:\ |
346 | 115 | No Flickr user id available (account: faker/than fake) | 121 | No Flickr user id available (account: faker/than fake) |
347 | 122 | Flickr.receive has completed, thread exiting. | ||
348 | 116 | """) | 123 | """) |
349 | 117 | 124 | ||
350 | 118 | @mock.patch('friends.utils.download.Soup.Message', | 125 | @mock.patch('friends.utils.download.Soup.Message', |
351 | @@ -129,7 +136,10 @@ | |||
352 | 129 | side_effect=side_effect): | 136 | side_effect=side_effect): |
353 | 130 | self.protocol('receive') | 137 | self.protocol('receive') |
354 | 131 | # No error message. | 138 | # No error message. |
356 | 132 | self.assertEqual(self.log_mock.empty(), '') | 139 | self.assertEqual(self.log_mock.empty(), """\ |
357 | 140 | Flickr.receive is starting in a new thread. | ||
358 | 141 | Flickr.receive has completed, thread exiting. | ||
359 | 142 | """) | ||
360 | 133 | # But also no photos. | 143 | # But also no photos. |
361 | 134 | self.assertEqual(TestModel.get_n_rows(), 0) | 144 | self.assertEqual(TestModel.get_n_rows(), 0) |
362 | 135 | 145 | ||
363 | @@ -145,6 +155,7 @@ | |||
364 | 145 | # AccessToken, but this fails. | 155 | # AccessToken, but this fails. |
365 | 146 | self.protocol('receive') | 156 | self.protocol('receive') |
366 | 147 | self.assertEqual(self.log_mock.empty(), """\ | 157 | self.assertEqual(self.log_mock.empty(), """\ |
367 | 158 | Flickr.receive is starting in a new thread. | ||
368 | 148 | Logging in to Flickr | 159 | Logging in to Flickr |
369 | 149 | No AccessToken in Flickr session:\ | 160 | No AccessToken in Flickr session:\ |
370 | 150 | {'TokenSecret': 'abc', 'username': 'Bob Dobbs', 'user_nsid': 'bob'} | 161 | {'TokenSecret': 'abc', 'username': 'Bob Dobbs', 'user_nsid': 'bob'} |
371 | @@ -154,6 +165,7 @@ | |||
372 | 154 | ... | 165 | ... |
373 | 155 | friends.errors.AuthorizationError:\ | 166 | friends.errors.AuthorizationError:\ |
374 | 156 | No Flickr user id available (account: faker/than fake) | 167 | No Flickr user id available (account: faker/than fake) |
375 | 168 | Flickr.receive has completed, thread exiting. | ||
376 | 157 | """) | 169 | """) |
377 | 158 | 170 | ||
378 | 159 | @mock.patch('friends.utils.download.Soup.Message', | 171 | @mock.patch('friends.utils.download.Soup.Message', |
379 | @@ -166,6 +178,7 @@ | |||
380 | 166 | # AccessToken, but this fails. | 178 | # AccessToken, but this fails. |
381 | 167 | self.protocol('receive') | 179 | self.protocol('receive') |
382 | 168 | self.assertEqual(self.log_mock.empty(), """\ | 180 | self.assertEqual(self.log_mock.empty(), """\ |
383 | 181 | Flickr.receive is starting in a new thread. | ||
384 | 169 | Logging in to Flickr | 182 | Logging in to Flickr |
385 | 170 | No Flickr authentication results received. | 183 | No Flickr authentication results received. |
386 | 171 | Flickr: No NSID available | 184 | Flickr: No NSID available |
387 | @@ -174,6 +187,7 @@ | |||
388 | 174 | ... | 187 | ... |
389 | 175 | friends.errors.AuthorizationError:\ | 188 | friends.errors.AuthorizationError:\ |
390 | 176 | No Flickr user id available (account: faker/than fake) | 189 | No Flickr user id available (account: faker/than fake) |
391 | 190 | Flickr.receive has completed, thread exiting. | ||
392 | 177 | """) | 191 | """) |
393 | 178 | 192 | ||
394 | 179 | @mock.patch('friends.utils.download.Soup.Message', | 193 | @mock.patch('friends.utils.download.Soup.Message', |
395 | 180 | 194 | ||
396 | === modified file 'friends/tests/test_logging.py' | |||
397 | --- friends/tests/test_logging.py 2012-10-13 01:27:15 +0000 | |||
398 | +++ friends/tests/test_logging.py 2012-10-20 00:36:21 +0000 | |||
399 | @@ -35,30 +35,23 @@ | |||
400 | 35 | def setUp(self): | 35 | def setUp(self): |
401 | 36 | # Preserve the original logger, but restore the global logging system | 36 | # Preserve the original logger, but restore the global logging system |
402 | 37 | # to pre-initialized state. | 37 | # to pre-initialized state. |
405 | 38 | self._logger = logging.getLogger('friends.service') | 38 | self._loggers = logging.Logger.manager.loggerDict.copy() |
406 | 39 | del logging.Logger.manager.loggerDict['friends.service'] | 39 | logging.Logger.manager.loggerDict.clear() |
407 | 40 | 40 | ||
408 | 41 | def tearDown(self): | 41 | def tearDown(self): |
411 | 42 | # Restore the original logger. | 42 | # Restore the original loggers. |
412 | 43 | logging.Logger.manager.loggerDict['friends.service'] = self._logger | 43 | logging.Logger.manager.loggerDict.update(self._loggers) |
413 | 44 | 44 | ||
414 | 45 | def test_logger_has_filehandler(self): | 45 | def test_logger_has_filehandler(self): |
415 | 46 | initialize() | 46 | initialize() |
418 | 47 | # The top level 'friends.service' logger should be available. | 47 | # The top level logger should be available. |
419 | 48 | log = logging.getLogger('friends.service') | 48 | log = logging.getLogger() |
420 | 49 | # Try to find the file opened by the default file handler. | 49 | # Try to find the file opened by the default file handler. |
421 | 50 | filenames = [] | 50 | filenames = [] |
422 | 51 | for handler in log.handlers: | 51 | for handler in log.handlers: |
423 | 52 | if hasattr(handler, 'baseFilename'): | 52 | if hasattr(handler, 'baseFilename'): |
424 | 53 | filenames.append(handler.baseFilename) | 53 | filenames.append(handler.baseFilename) |
433 | 54 | self.assertEqual(len(filenames), 1) | 54 | self.assertGreater(len(filenames), 0) |
426 | 55 | |||
427 | 56 | def _get_log_filename(self, log): | ||
428 | 57 | filenames = [] | ||
429 | 58 | for handler in log.handlers: | ||
430 | 59 | if hasattr(handler, 'baseFilename'): | ||
431 | 60 | filenames.append(handler.baseFilename) | ||
432 | 61 | return filenames | ||
434 | 62 | 55 | ||
435 | 63 | def test_logger_message(self): | 56 | def test_logger_message(self): |
436 | 64 | # Write an error message to the log and test that it shows up. | 57 | # Write an error message to the log and test that it shows up. |
437 | @@ -67,11 +60,7 @@ | |||
438 | 67 | logfile = os.path.join(tempdir, 'friends-test.log') | 60 | logfile = os.path.join(tempdir, 'friends-test.log') |
439 | 68 | initialize(filename=logfile) | 61 | initialize(filename=logfile) |
440 | 69 | # Get another handle on the log file. | 62 | # Get another handle on the log file. |
446 | 70 | log = logging.getLogger('friends.service') | 63 | log = logging.getLogger() |
442 | 71 | # Try to find the file opened by the default file handler. | ||
443 | 72 | filenames = self._get_log_filename(log) | ||
444 | 73 | self.assertEqual(len(filenames), 1) | ||
445 | 74 | logfile = filenames[0] | ||
447 | 75 | self.assertEqual(os.stat(logfile).st_size, 0) | 64 | self.assertEqual(os.stat(logfile).st_size, 0) |
448 | 76 | # Log messages at INFO or higher should be written. | 65 | # Log messages at INFO or higher should be written. |
449 | 77 | log.info('friends at your service') | 66 | log.info('friends at your service') |
450 | @@ -81,12 +70,11 @@ | |||
451 | 81 | contents = fp.read() | 70 | contents = fp.read() |
452 | 82 | lines = contents.splitlines() | 71 | lines = contents.splitlines() |
453 | 83 | self.assertEqual(len(lines), 1) | 72 | self.assertEqual(len(lines), 1) |
456 | 84 | # The log message will have a variable timestamp at the front, so | 73 | # The log message will have a variable timestamp, so ignore |
457 | 85 | # ignore that, but check everything else. | 74 | # that, but check everything else. |
458 | 86 | self.assertRegex( | 75 | self.assertRegex( |
459 | 87 | lines[0], | 76 | lines[0], |
462 | 88 | r'friends.service\s+MainThread\s+:\s+INFO\s+-\s+' | 77 | r'INFO\s+MainThread.*root\s+friends at your service') |
461 | 89 | r'friends at your service') | ||
463 | 90 | 78 | ||
464 | 91 | def test_console_logger(self): | 79 | def test_console_logger(self): |
465 | 92 | # The logger can support an optional console logger. | 80 | # The logger can support an optional console logger. |
466 | @@ -94,10 +82,10 @@ | |||
467 | 94 | self.addCleanup(shutil.rmtree, tempdir) | 82 | self.addCleanup(shutil.rmtree, tempdir) |
468 | 95 | logfile = os.path.join(tempdir, 'friends-test.log') | 83 | logfile = os.path.join(tempdir, 'friends-test.log') |
469 | 96 | initialize(console=True, filename=logfile) | 84 | initialize(console=True, filename=logfile) |
471 | 97 | log = logging.getLogger('friends.service') | 85 | log = logging.getLogger() |
472 | 98 | # Can we do better than testing that there are now two handlers for | 86 | # Can we do better than testing that there are now two handlers for |
473 | 99 | # the logger? | 87 | # the logger? |
475 | 100 | self.assertEqual(2, sum(1 for handler in log.handlers)) | 88 | self.assertEqual(3, sum(1 for handler in log.handlers)) |
476 | 101 | 89 | ||
477 | 102 | def test_default_logger_level(self): | 90 | def test_default_logger_level(self): |
478 | 103 | # By default, the logger level is INFO. | 91 | # By default, the logger level is INFO. |
479 | @@ -106,11 +94,7 @@ | |||
480 | 106 | logfile = os.path.join(tempdir, 'friends-test.log') | 94 | logfile = os.path.join(tempdir, 'friends-test.log') |
481 | 107 | initialize(filename=logfile) | 95 | initialize(filename=logfile) |
482 | 108 | # Get another handle on the log file. | 96 | # Get another handle on the log file. |
488 | 109 | log = logging.getLogger('friends.service') | 97 | log = logging.getLogger() |
484 | 110 | # Try to find the file opened by the default file handler. | ||
485 | 111 | filenames = self._get_log_filename(log) | ||
486 | 112 | self.assertEqual(len(filenames), 1) | ||
487 | 113 | logfile = filenames[0] | ||
489 | 114 | # By default, debug messages won't get written since they are less | 98 | # By default, debug messages won't get written since they are less |
490 | 115 | # severe than INFO. | 99 | # severe than INFO. |
491 | 116 | log.debug('friends is ready') | 100 | log.debug('friends is ready') |
492 | @@ -123,11 +107,7 @@ | |||
493 | 123 | logfile = os.path.join(tempdir, 'friends-test.log') | 107 | logfile = os.path.join(tempdir, 'friends-test.log') |
494 | 124 | initialize(filename=logfile, debug=True) | 108 | initialize(filename=logfile, debug=True) |
495 | 125 | # Get another handle on the log file. | 109 | # Get another handle on the log file. |
501 | 126 | log = logging.getLogger('friends.service') | 110 | log = logging.getLogger() |
497 | 127 | # Try to find the file opened by the default file handler. | ||
498 | 128 | filenames = self._get_log_filename(log) | ||
499 | 129 | self.assertEqual(len(filenames), 1) | ||
500 | 130 | logfile = filenames[0] | ||
502 | 131 | log.debug('friends is ready') | 111 | log.debug('friends is ready') |
503 | 132 | self.assertGreater(os.stat(logfile).st_size, 0) | 112 | self.assertGreater(os.stat(logfile).st_size, 0) |
504 | 133 | # Read the contents, which should be just one line of output. | 113 | # Read the contents, which should be just one line of output. |
505 | @@ -139,5 +119,4 @@ | |||
506 | 139 | # ignore that, but check everything else. | 119 | # ignore that, but check everything else. |
507 | 140 | self.assertRegex( | 120 | self.assertRegex( |
508 | 141 | lines[0], | 121 | lines[0], |
511 | 142 | r'friends.service\s+MainThread\s+:\s+DEBUG\s+-\s+' | 122 | r'DEBUG\s+MainThread.*root\s+friends is ready') |
510 | 143 | r'friends is ready') | ||
512 | 144 | 123 | ||
513 | === modified file 'friends/utils/account.py' | |||
514 | --- friends/utils/account.py 2012-10-18 18:41:58 +0000 | |||
515 | +++ friends/utils/account.py 2012-10-20 00:36:21 +0000 | |||
516 | @@ -31,7 +31,7 @@ | |||
517 | 31 | from friends.utils.model import COLUMN_INDICES, Model | 31 | from friends.utils.model import COLUMN_INDICES, Model |
518 | 32 | 32 | ||
519 | 33 | 33 | ||
521 | 34 | log = logging.getLogger('friends.service') | 34 | log = logging.getLogger(__name__) |
522 | 35 | 35 | ||
523 | 36 | 36 | ||
524 | 37 | class AccountManager: | 37 | class AccountManager: |
525 | 38 | 38 | ||
526 | === modified file 'friends/utils/authentication.py' | |||
527 | --- friends/utils/authentication.py 2012-10-13 01:27:15 +0000 | |||
528 | +++ friends/utils/authentication.py 2012-10-20 00:36:21 +0000 | |||
529 | @@ -21,37 +21,37 @@ | |||
530 | 21 | 21 | ||
531 | 22 | 22 | ||
532 | 23 | import logging | 23 | import logging |
533 | 24 | import time | ||
534 | 24 | 25 | ||
535 | 25 | from gi.repository import GObject, Signon | 26 | from gi.repository import GObject, Signon |
536 | 26 | GObject.threads_init(None) | 27 | GObject.threads_init(None) |
537 | 27 | 28 | ||
538 | 28 | 29 | ||
539 | 30 | log = logging.getLogger(__name__) | ||
540 | 31 | |||
541 | 32 | |||
542 | 29 | class Authentication: | 33 | class Authentication: |
544 | 30 | def __init__(self, account, log=None): | 34 | def __init__(self, account): |
545 | 31 | self.account = account | 35 | self.account = account |
546 | 32 | self.log = (logging.getLogger('friends.service') | ||
547 | 33 | if log is None | ||
548 | 34 | else log) | ||
549 | 35 | self._reply = None | 36 | self._reply = None |
550 | 36 | self._authenticating = False | ||
551 | 37 | 37 | ||
552 | 38 | def login(self): | 38 | def login(self): |
553 | 39 | auth = self.account.auth | 39 | auth = self.account.auth |
554 | 40 | self.auth_session = Signon.AuthSession.new(auth.id, auth.method) | 40 | self.auth_session = Signon.AuthSession.new(auth.id, auth.method) |
555 | 41 | self._authenticating = True | ||
556 | 42 | self._loop = GObject.MainLoop() | ||
557 | 43 | self.auth_session.process( | 41 | self.auth_session.process( |
558 | 44 | auth.parameters, auth.mechanism, | 42 | auth.parameters, auth.mechanism, |
559 | 45 | self._login_cb, None) | 43 | self._login_cb, None) |
562 | 46 | if self._authenticating: | 44 | timeout = 30 |
563 | 47 | self._loop.run() | 45 | while self._reply is None and timeout > 0: |
564 | 46 | # We're building a synchronous API on top of an inherently | ||
565 | 47 | # async library, so we need to block this thread until the | ||
566 | 48 | # callback gets called to give us the response to return. | ||
567 | 49 | time.sleep(0.5) | ||
568 | 50 | timeout -= 1 | ||
569 | 48 | return self._reply | 51 | return self._reply |
570 | 49 | 52 | ||
571 | 50 | def _login_cb(self, session, reply, error, user_data): | 53 | def _login_cb(self, session, reply, error, user_data): |
573 | 51 | self._authenticating = False | 54 | self._reply = reply |
574 | 52 | if error: | 55 | if error: |
580 | 53 | self.log.error('Got authentication error: {}', error.message) | 56 | log.error('Got authentication error: {}'.format(error.message)) |
581 | 54 | else: | 57 | log.debug('Login completed') |
577 | 55 | self._reply = reply | ||
578 | 56 | self.log.debug('Login completed') | ||
579 | 57 | self._loop.quit() | ||
582 | 58 | 58 | ||
583 | === modified file 'friends/utils/avatar.py' | |||
584 | --- friends/utils/avatar.py 2012-10-13 01:27:15 +0000 | |||
585 | +++ friends/utils/avatar.py 2012-10-20 00:36:21 +0000 | |||
586 | @@ -31,7 +31,7 @@ | |||
587 | 31 | from friends.utils.download import Downloader | 31 | from friends.utils.download import Downloader |
588 | 32 | 32 | ||
589 | 33 | 33 | ||
591 | 34 | log = logging.getLogger('friends.avatars') | 34 | log = logging.getLogger(__name__) |
592 | 35 | CACHE_DIR = os.path.realpath(os.path.join( | 35 | CACHE_DIR = os.path.realpath(os.path.join( |
593 | 36 | GLib.get_user_cache_dir(), 'friends', 'avatars')) | 36 | GLib.get_user_cache_dir(), 'friends', 'avatars')) |
594 | 37 | CACHE_AGE = timedelta(weeks=4) | 37 | CACHE_AGE = timedelta(weeks=4) |
595 | 38 | 38 | ||
596 | === modified file 'friends/utils/base.py' | |||
597 | --- friends/utils/base.py 2012-10-16 18:58:49 +0000 | |||
598 | +++ friends/utils/base.py 2012-10-20 00:36:21 +0000 | |||
599 | @@ -52,7 +52,7 @@ | |||
600 | 52 | _publish_lock = threading.Lock() | 52 | _publish_lock = threading.Lock() |
601 | 53 | 53 | ||
602 | 54 | 54 | ||
604 | 55 | log = logging.getLogger('friends.service') | 55 | log = logging.getLogger(__name__) |
605 | 56 | 56 | ||
606 | 57 | 57 | ||
607 | 58 | def feature(method): | 58 | def feature(method): |
608 | @@ -105,9 +105,10 @@ | |||
609 | 105 | class _OperationThread(threading.Thread): | 105 | class _OperationThread(threading.Thread): |
610 | 106 | """Catch, log, and swallow all exceptions in the sub-thread.""" | 106 | """Catch, log, and swallow all exceptions in the sub-thread.""" |
611 | 107 | 107 | ||
613 | 108 | def __init__(self, barrier, *args, **kws): | 108 | def __init__(self, barrier, *args, identifier=None, **kws): |
614 | 109 | # The barrier will only be provided when the system is under test. | 109 | # The barrier will only be provided when the system is under test. |
615 | 110 | self._barrier = barrier | 110 | self._barrier = barrier |
616 | 111 | self._id = identifier | ||
617 | 111 | super().__init__(*args, **kws) | 112 | super().__init__(*args, **kws) |
618 | 112 | 113 | ||
619 | 113 | # Always run these as daemon threads, so they don't block the main thread, | 114 | # Always run these as daemon threads, so they don't block the main thread, |
620 | @@ -115,10 +116,12 @@ | |||
621 | 115 | daemon = True | 116 | daemon = True |
622 | 116 | 117 | ||
623 | 117 | def run(self): | 118 | def run(self): |
624 | 119 | log.debug('{} is starting in a new thread.'.format(self._id)) | ||
625 | 118 | try: | 120 | try: |
626 | 119 | super().run() | 121 | super().run() |
627 | 120 | except Exception: | 122 | except Exception: |
628 | 121 | log.exception('Friends operation exception:\n') | 123 | log.exception('Friends operation exception:\n') |
629 | 124 | log.debug('{} has completed, thread exiting.'.format(self._id)) | ||
630 | 122 | # If the system is under test, indicate that we've reached the | 125 | # If the system is under test, indicate that we've reached the |
631 | 123 | # barrier, so that the main thread, i.e. the test thread waiting for | 126 | # barrier, so that the main thread, i.e. the test thread waiting for |
632 | 124 | # the results, can then proceed. | 127 | # the results, can then proceed. |
633 | @@ -160,6 +163,8 @@ | |||
634 | 160 | # thread to assert the results of the sub-thread. | 163 | # thread to assert the results of the sub-thread. |
635 | 161 | barrier = (threading.Barrier(parties=2) if Base._SYNCHRONIZE else None) | 164 | barrier = (threading.Barrier(parties=2) if Base._SYNCHRONIZE else None) |
636 | 162 | _OperationThread(barrier, | 165 | _OperationThread(barrier, |
637 | 166 | identifier='{}.{}'.format(self.__class__.__name__, | ||
638 | 167 | operation), | ||
639 | 163 | target=method, args=args, kwargs=kwargs).start() | 168 | target=method, args=args, kwargs=kwargs).start() |
640 | 164 | # When under synchronous testing, wait until the sub-thread completes | 169 | # When under synchronous testing, wait until the sub-thread completes |
641 | 165 | # before returning. | 170 | # before returning. |
642 | @@ -299,7 +304,7 @@ | |||
643 | 299 | log.debug('{} to {}'.format( | 304 | log.debug('{} to {}'.format( |
644 | 300 | 'Re-authenticating' if old_token else 'Logging in', protocol)) | 305 | 'Re-authenticating' if old_token else 'Logging in', protocol)) |
645 | 301 | 306 | ||
647 | 302 | result = Authentication(self._account, log).login() | 307 | result = Authentication(self._account).login() |
648 | 303 | if result is None: | 308 | if result is None: |
649 | 304 | log.error( | 309 | log.error( |
650 | 305 | 'No {} authentication results received.'.format(protocol)) | 310 | 'No {} authentication results received.'.format(protocol)) |
651 | 306 | 311 | ||
652 | === modified file 'friends/utils/download.py' | |||
653 | --- friends/utils/download.py 2012-10-18 18:41:54 +0000 | |||
654 | +++ friends/utils/download.py 2012-10-20 00:36:21 +0000 | |||
655 | @@ -31,7 +31,7 @@ | |||
656 | 31 | from urllib.error import HTTPError | 31 | from urllib.error import HTTPError |
657 | 32 | from urllib.parse import urlencode | 32 | from urllib.parse import urlencode |
658 | 33 | 33 | ||
660 | 34 | log = logging.getLogger('friends.service') | 34 | log = logging.getLogger(__name__) |
661 | 35 | 35 | ||
662 | 36 | 36 | ||
663 | 37 | # Global libsoup session instance. | 37 | # Global libsoup session instance. |
664 | @@ -139,16 +139,9 @@ | |||
665 | 139 | message = self._build_request() | 139 | message = self._build_request() |
666 | 140 | _soup.send_message(message) | 140 | _soup.send_message(message) |
667 | 141 | if message.status_code != 200: | 141 | if message.status_code != 200: |
678 | 142 | # Even though we're using libsoup instead of Python's urllib | 142 | log.error('{}: {} {}'.format(self.url, |
679 | 143 | # libraries, it's helpful for clients to receive an exception when | 143 | message.status_code, |
680 | 144 | # non-success error codes are received. This lets the clients do | 144 | message.reason_phrase)) |
671 | 145 | # additional work if they want, and it prevents rate limiting from | ||
672 | 146 | # occurring. | ||
673 | 147 | raise HTTPError(self.url, | ||
674 | 148 | message.status_code, | ||
675 | 149 | message.reason_phrase, | ||
676 | 150 | self.headers, | ||
677 | 151 | None) | ||
681 | 152 | yield message | 145 | yield message |
682 | 153 | self._rate_limiter.update(message) | 146 | self._rate_limiter.update(message) |
683 | 154 | 147 | ||
684 | 155 | 148 | ||
685 | === modified file 'friends/utils/logging.py' | |||
686 | --- friends/utils/logging.py 2012-10-13 01:27:15 +0000 | |||
687 | +++ friends/utils/logging.py 2012-10-20 00:36:21 +0000 | |||
688 | @@ -19,15 +19,25 @@ | |||
689 | 19 | import errno | 19 | import errno |
690 | 20 | import logging | 20 | import logging |
691 | 21 | import logging.handlers | 21 | import logging.handlers |
692 | 22 | import oauthlib.oauth1 | ||
693 | 22 | 23 | ||
694 | 23 | from gi.repository import GLib | 24 | from gi.repository import GLib |
695 | 24 | 25 | ||
696 | 25 | 26 | ||
697 | 27 | # Set a global default of no logging. This is a workaround for a bug | ||
698 | 28 | # where we were getting duplicated log records. | ||
699 | 29 | logging.basicConfig(filename='/dev/null', level=100) | ||
700 | 30 | |||
701 | 31 | |||
702 | 32 | # Disable logging in oauthlib because it is very verbose. | ||
703 | 33 | oauthlib.oauth1.rfc5849.logging.debug = lambda *ignore: None | ||
704 | 34 | |||
705 | 35 | |||
706 | 26 | LOG_FILENAME = os.path.join( | 36 | LOG_FILENAME = os.path.join( |
707 | 27 | os.path.realpath(os.path.abspath(GLib.get_user_cache_dir())), | 37 | os.path.realpath(os.path.abspath(GLib.get_user_cache_dir())), |
708 | 28 | 'friends', 'friends.log') | 38 | 'friends', 'friends.log') |
711 | 29 | LOG_FORMAT = '{asctime} - {name:12} {threadName:14}: {levelname:8} - {message}' | 39 | LOG_FORMAT = '{levelname:5} {threadName:10} {asctime} {name:18} {message}' |
712 | 30 | CSL_FORMAT = '{name:12} {threadName:12}: {levelname:8} {message}' | 40 | CSL_FORMAT = LOG_FORMAT.replace(' {asctime}', '') |
713 | 31 | 41 | ||
714 | 32 | 42 | ||
715 | 33 | def initialize(console=False, debug=False, filename=None): | 43 | def initialize(console=False, debug=False, filename=None): |
716 | @@ -48,11 +58,7 @@ | |||
717 | 48 | except OSError as error: | 58 | except OSError as error: |
718 | 49 | if error.errno != errno.EEXIST: | 59 | if error.errno != errno.EEXIST: |
719 | 50 | raise | 60 | raise |
725 | 51 | log = logging.getLogger('friends.service') | 61 | |
721 | 52 | if debug: | ||
722 | 53 | log.setLevel(logging.DEBUG) | ||
723 | 54 | else: | ||
724 | 55 | log.setLevel(logging.INFO) | ||
726 | 56 | # Install a rotating log file handler. XXX There should be a | 62 | # Install a rotating log file handler. XXX There should be a |
727 | 57 | # configuration file rather than hard-coded values. | 63 | # configuration file rather than hard-coded values. |
728 | 58 | text_handler = logging.handlers.RotatingFileHandler( | 64 | text_handler = logging.handlers.RotatingFileHandler( |
729 | @@ -60,9 +66,16 @@ | |||
730 | 60 | # Use str.format() style format strings. | 66 | # Use str.format() style format strings. |
731 | 61 | text_formatter = logging.Formatter(LOG_FORMAT, style='{') | 67 | text_formatter = logging.Formatter(LOG_FORMAT, style='{') |
732 | 62 | text_handler.setFormatter(text_formatter) | 68 | text_handler.setFormatter(text_formatter) |
734 | 63 | log.addHandler(text_handler) | 69 | |
735 | 70 | console_handler = logging.StreamHandler() | ||
736 | 71 | console_formatter = logging.Formatter(CSL_FORMAT, style='{') | ||
737 | 72 | console_handler.setFormatter(console_formatter) | ||
738 | 73 | |||
739 | 74 | log = logging.getLogger() | ||
740 | 75 | if debug: | ||
741 | 76 | log.setLevel(logging.DEBUG) | ||
742 | 77 | else: | ||
743 | 78 | log.setLevel(logging.INFO) | ||
744 | 64 | if console: | 79 | if console: |
745 | 65 | console_handler = logging.StreamHandler() | ||
746 | 66 | console_formatter = logging.Formatter(CSL_FORMAT, style='{') | ||
747 | 67 | console_handler.setFormatter(console_formatter) | ||
748 | 68 | log.addHandler(console_handler) | 80 | log.addHandler(console_handler) |
749 | 81 | log.addHandler(text_handler) | ||
750 | 69 | 82 | ||
751 | === modified file 'friends/utils/menus.py' | |||
752 | --- friends/utils/menus.py 2012-10-13 01:27:15 +0000 | |||
753 | +++ friends/utils/menus.py 2012-10-20 00:36:21 +0000 | |||
754 | @@ -34,7 +34,7 @@ | |||
755 | 34 | 34 | ||
756 | 35 | 35 | ||
757 | 36 | DESKTOP_ID = 'friends.desktop' | 36 | DESKTOP_ID = 'friends.desktop' |
759 | 37 | log = logging.getLogger('friends.service') | 37 | log = logging.getLogger(__name__) |
760 | 38 | 38 | ||
761 | 39 | 39 | ||
762 | 40 | def helper(executable): | 40 | def helper(executable): |
763 | 41 | 41 | ||
764 | === modified file 'tools/debug_live.py' | |||
765 | --- tools/debug_live.py 2012-10-13 01:27:15 +0000 | |||
766 | +++ tools/debug_live.py 2012-10-20 00:36:21 +0000 | |||
767 | @@ -20,30 +20,29 @@ | |||
768 | 20 | """ | 20 | """ |
769 | 21 | 21 | ||
770 | 22 | import sys | 22 | import sys |
771 | 23 | import time | ||
772 | 24 | import logging | ||
773 | 23 | 25 | ||
774 | 24 | sys.path.insert(0, '.') | 26 | sys.path.insert(0, '.') |
775 | 25 | 27 | ||
776 | 26 | from gi.repository import GObject | 28 | from gi.repository import GObject |
777 | 29 | from friends.utils.logging import initialize | ||
778 | 27 | from friends.utils.account import AccountManager | 30 | from friends.utils.account import AccountManager |
779 | 28 | from friends.utils.base import Base | 31 | from friends.utils.base import Base |
780 | 29 | from friends.utils.model import Model | 32 | from friends.utils.model import Model |
781 | 30 | 33 | ||
788 | 31 | 34 | # Print all logs for debugging purposes | |
789 | 32 | # Ensure synchronous operation of Base.__call__() for easier testing. | 35 | initialize(debug=True, console=True) |
790 | 33 | Base._SYNCHRONIZE = True | 36 | |
791 | 34 | 37 | ||
792 | 35 | 38 | log = logging.getLogger('friends.debug_live') | |
793 | 36 | def refresh(account): | 39 | |
794 | 40 | |||
795 | 41 | def row_added(model, itr): | ||
796 | 42 | row = model.get_row(itr) | ||
797 | 43 | print(row) | ||
798 | 44 | log.info('ROWS: {}'.format(len(model))) | ||
799 | 37 | print() | 45 | print() |
800 | 38 | print('#' * 80) | ||
801 | 39 | print('Performing "{}" operation!'.format(args[0])) | ||
802 | 40 | print('#' * 80) | ||
803 | 41 | |||
804 | 42 | account.protocol(*args) | ||
805 | 43 | for row in Model: | ||
806 | 44 | print([col for col in row]) | ||
807 | 45 | print() | ||
808 | 46 | print('ROWS: ', len(Model)) | ||
809 | 47 | 46 | ||
810 | 48 | 47 | ||
811 | 49 | if __name__ == '__main__': | 48 | if __name__ == '__main__': |
812 | @@ -56,14 +55,16 @@ | |||
813 | 56 | found = False | 55 | found = False |
814 | 57 | a = AccountManager(None) | 56 | a = AccountManager(None) |
815 | 58 | 57 | ||
816 | 58 | Model.connect('row-added', row_added) | ||
817 | 59 | |||
818 | 59 | for account_id, account in a._accounts.items(): | 60 | for account_id, account in a._accounts.items(): |
819 | 60 | if account_id.endswith(protocol): | 61 | if account_id.endswith(protocol): |
820 | 61 | found = True | 62 | found = True |
823 | 62 | refresh(account) | 63 | account.protocol(*args) |
822 | 63 | GObject.timeout_add_seconds(300, refresh, account) | ||
824 | 64 | 64 | ||
825 | 65 | if not found: | 65 | if not found: |
828 | 66 | print('No {} account found in your Ubuntu Online Accounts!'.format( | 66 | log.error('No {} found in Ubuntu Online Accounts!'.format(protocol)) |
827 | 67 | protocol)) | ||
829 | 68 | else: | 67 | else: |
831 | 69 | GObject.MainLoop().run() | 68 | loop = GObject.MainLoop() |
832 | 69 | GObject.timeout_add_seconds(10, loop.quit) | ||
833 | 70 | loop.run() |
This branch also initiates a dispatcher.Refresh on friends-service launch, so that we don't have to wait 15 minutes for the first batch of data to be downloaded ;-)