Occasional 401 Unauthorized errors

[roitk]

Hello,

I started playing around with the hangups client. After going through the hangups --manual-login flow, I noticed that auth would occasionally get back a 401 at various points during startup.

Here is an example of a failed request (hangups -d):

2020-07-19 15:14:37,165 - hangups.conversation - DEBUG - Need to request additional users: [REDACTED]
2020-07-19 15:14:37,166 - hangups.client - DEBUG - Sending Protocol Buffer request contacts/getentitybyid:                                                                                                                                   request_header {                                                                                                                                                                                                                               client_version {                                                                                                                                                                                                                               client_id: CLIENT_ID_WEB_HANGOUTS                                                                                                                                                                                                            major_version: "hangups-0.4.10"                                                                                                                                                                                                            }                                                                                                                                                                                                                                            language_code: "en"                                                                                                                                                                                                                        }                                                                                                                                                                                                                                            batch_lookup_spec {
  gaia_id: "[REDACTED]"
  create_offnetwork_gaia: true
} 
... a few more batch_lookup_specs here

2020-07-19 15:14:37,166 - hangups.http_utils - DEBUG - Sending request post https://clients6.google.com/chat/v1/contacts/getentitybyid:
b'\n\x18\n\x12\x08,\x1a\x0ehangups-0.4.10"\x02en\x1a\x19\n\x151002092520157925658570\x01\x1a\x19\n\x151110855751085305736940\x01\x1a\x19\n\x151034416763985734618740\x01\x1a\x19\n\x151054284067634721792680\x01\x1a\x19\n\x151137431781847534405150\x01\x1a\x19\n\x151066938722888582967390\x01\x1a\x19\n\x151092469008738011731870\x01\x1a\x19\n\x151090494791198303989600\x01\x1a\x19\n\x151116147841406809188710\x01\x1a\x19\n\x151121678349796502683010\x01\x1a\x19\n\x151023287790912805617580\x01\x1a\x19\n\x151127389352522079023980\x01\x1a\x19\n\x151183137740830292626030\x01\x1a\x19\n\x151153889384130258240030\x01\x1a\x19\n\x151169723154763970166200\x01\x1a\x19\n\x151156381712822134806040\x01\x1a\x19\n\x151149227081059963551960\x01\x1a\x19\n\x151134324385114740644120\x01\x1a\x19\n\x151103193606894047002800\x01\x1a\x19\n\x151054912508469594866030\x01\x1a\x19\n\x151116410388272797115060\x01\x1a\x19\n\x151044965291387267730230\x01\x1a\x19\n\x151047504591851023218980\x01\x1a\x19\n\x151065385661348176532830\x01\x1a\x19\n\x151036455332675721099880\x01\x1a\x19\n\x151113398328797980158640\x01\x1a\x19\n\x151069395679454391133860\x01'
2020-07-19 15:14:37,172 - hangups.http_utils - DEBUG - Received response 401 Unauthorized:
b'{\n  "error": {\n    "code": 401,\n    "message": "Request had invalid authentication credentials. Expected OAuth 2 access token, login cookie or other valid authentication credential. See https://developers.google.com/identity/sign-in/web/devconsole-project.",\n    "errors": [\n      {\n        "message": "Invalid Credentials",\n        "domain": "global",\n        "reason": "authError",\n        "location": "Authorization",\n        "locationType": "header"\n      }\n    ],\n    "status": "UNAUTHENTICATED"\n  }\n}\n'
2020-07-19 15:14:37,172 - hangups.http_utils - INFO - Request returned unexpected status: 401 Unauthorized
2020-07-19 15:14:37,172 - hangups.conversation - WARNING - Failed to request missing users: Request return unexpected status: 401: Unauthorized
2020-07-19 15:14:37,172 - hangups.client - DEBUG - Sending Protocol Buffer request contacts/getselfinfo:
request_header {
  client_version {
    client_id: CLIENT_ID_WEB_HANGOUTS
    major_version: "hangups-0.4.10"
  }
  language_code: "en"
}

2020-07-19 15:14:37,172 - hangups.http_utils - DEBUG - Sending request post https://clients6.google.com/chat/v1/contacts/getselfinfo:
b'\n\x18\n\x12\x08,\x1a\x0ehangups-0.4.10"\x02en'
2020-07-19 15:14:37,179 - hangups.http_utils - DEBUG - Received response 401 Unauthorized:
b'{\n  "error": {\n    "code": 401,\n    "message": "Request had invalid authentication credentials. Expected OAuth 2 access token, login cookie or other valid authentication credential. See https://developers.google.com/identity/sign-in/web/devconsole-project.",\n    "errors": [\n      {\n        "message": "Invalid Credentials",\n        "domain": "global",\n        "reason": "authError",\n        "location": "Authorization",\n        "locationType": "header"\n      }\n    ],\n    "status": "UNAUTHENTICATED"\n  }\n}\n'
2020-07-19 15:14:37,179 - hangups.http_utils - INFO - Request returned unexpected status: 401 Unauthorized
2020-07-19 15:14:37,179 - hangups.channel - WARNING - Long-polling request failed: Request return unexpected status: 401: Unauthorized

My very next hangups -d succeeded. I didn't change any config files or the command line. The location in the logs of the above failed rpc (getselfinfo):

2020-07-19 14:57:29,260 - hangups.http_utils - DEBUG - Sending request post https://clients6.google.com/chat/v1/contacts/getselfinfo:
b'\n\x18\n\x12\x08,\x1a\x0ehangups-0.4.10"\x02en'
2020-07-19 14:57:29,322 - hangups.http_utils - DEBUG - Received response 200 OK:

It's not always getselfinfo that fails. Sometimes it's another RPC like syncrecentconversations.

[Terrance]

I've started seeing this too, on several accounts as of a few days ago:

[2020-09-02 08:38:20,770 DEBUG hangups.client] Sending Protocol Buffer request conversations/syncrecentconversations:
request_header {
  client_version {
    client_id: CLIENT_ID_WEB_HANGOUTS
    major_version: "hangups-0.4.9"
  }
  language_code: "en"
}
last_event_timestamp: 1583436098041776
max_conversations: 100
max_events_per_conversation: 1
sync_filter: SYNC_FILTER_INBOX
sync_filter: SYNC_FILTER_ARCHIVED

[2020-09-02 08:38:20,770 DEBUG hangups.http_utils] Sending request post https://clients6.google.com/chat/v1/conversations/syncrecentconversations:
b'\n\x17\n\x11\x08,\x1a\rhangups-0.4.9"\x02en\x10\xb0\xef\x97\x91\x87\x84\xe8\x02\x18d \x01(\x01(\x02'
[2020-09-02 08:38:20,883 DEBUG hangups.http_utils] Received response 401 Unauthorized:
b'{\n  "error": {\n    "code": 401,\n    "message": "Request had invalid authentication credentials. Expected OAuth 2 access token, login cookie or other valid authentication credential. See https://developers.google.com/identity/sign-in/web/devconsole-project.",\n    "errors": [\n      {\n        "message": "Invalid Credentials",\n        "domain": "global",\n        "reason": "authError",\n        "location": "Authorization",\n        "locationType": "header"\n      }\n    ],\n    "status": "UNAUTHENTICATED"\n  }\n}\n'
[2020-09-02 08:38:20,884 INFO  hangups.http_utils] Request returned unexpected status: 401 Unauthorized

This will get thrown part way through await hangups.build_user_conversation_list(client), seemingly randomly:

Traceback (most recent call last):
  File "/opt/venv/lib/python3.6/site-packages/hangups/conversation.py", line 30, in build_user_conversation_list
    conv_states, sync_timestamp = await _sync_all_conversations(client)
  File "/opt/venv/lib/python3.6/site-packages/hangups/conversation.py", line 110, in _sync_all_conversations
    response = await client.sync_recent_conversations(request)
  File "/opt/venv/lib/python3.6/site-packages/hangups/client.py", line 674, in sync_recent_conversations
    response)
  File "/opt/venv/lib/python3.6/site-packages/hangups/client.py", line 417, in _pb_request
    request_pb.SerializeToString()
  File "/opt/venv/lib/python3.6/site-packages/hangups/client.py", line 470, in _base_request
    'post', url, headers=headers, params=params, data=data,
  File "/opt/venv/lib/python3.6/site-packages/hangups/http_utils.py", line 88, in fetch
    .format(res.status, res.reason)
hangups.exceptions.NetworkError: Request return unexpected status: 401: Unauthorized

For a large account (in the order of thousands of conversations) I've yet to get a complete call without it falling over.

[ewah]

monkey patching!...

[root@ip-x hangups]# diff /usr/local/lib/python3.5/site-packages/hangups/http_utils.py ~/orig.http_utils.py
23,25d22
< class UnauthorizedException(Exception):
<   pass
<
70,74d66
<
<                 #
<                 if res.status == 401:
<                     raise UnauthorizedException("got 401?")
<
83,84d74
<             except UnauthorizedException:
<                 error_msg = 'got 401 for url: ' + url

(that should probably be rolled into a configuration option or something)

[Terrance]

Instead of masking the issue, you can force a retry on 401:

diff --git hangups/http_utils.py hangups/http_utils.py
index dd196e8..5138071 100644
--- a/hangups/http_utils.py
+++ b/hangups/http_utils.py
@@ -68,4 +68,8 @@ class Session(object):
                 logger.debug('Received response %d %s:\n%r',
                              res.status, res.reason, body)
+                if res.status == 401:
+                    logger.debug('Forcing retry on unauthorized response')
+                    error_msg = 'Unauthorized'
+                    continue
             except asyncio.TimeoutError:
                 error_msg = 'Request timed out'

[ewah]

If it uses up MAX_RETRIES, I'd like to see it in raise exceptions.NetworkError(error_msg)

2020-09-02 16:32:24 INFO hangups.http_utils: Request attempt 0 failed: got 401 for url: https://clients6.google.com/chat/v1/contacts/getentitybyid
2020-09-02 16:32:24 INFO hangups.http_utils: Request attempt 1 failed: got 401 for url: https://clients6.google.com/chat/v1/contacts/getentitybyid
2020-09-02 16:32:24 INFO hangups.http_utils: Request attempt 2 failed: got 401 for url: https://clients6.google.com/chat/v1/contacts/getentitybyid
2020-09-02 16:32:24 INFO hangups.http_utils: Request failed after 3 attempts
2020-09-02 16:32:24 ERROR permamem: getentitybyid(): FAILED for chunk ['112457203303767596152', '108883278449577090918', '111203654751789510826', '104319699147571484482']
Traceback (most recent call last):
  File "/home/hangupsbot/hangupsbot-official/hangupsbot/permamem.py", line 226, in get_users_from_query
    _response = yield from self.bot._client.get_entity_by_id(_request)
  File "/usr/local/lib/python3.5/site-packages/hangups/client.py", line 527, in get_entity_by_id
    get_entity_by_id_request, response)
  File "/usr/local/lib/python3.5/site-packages/hangups/client.py", line 416, in _pb_request
    request_pb.SerializeToString()
  File "/usr/local/lib/python3.5/site-packages/hangups/client.py", line 469, in _base_request
    'post', url, headers=headers, params=params, data=data,
  File "/usr/local/lib/python3.5/site-packages/hangups/http_utils.py", line 90, in fetch
    raise exceptions.NetworkError(error_msg)
hangups.exceptions.NetworkError: got 401 for url: https://clients6.google.com/chat/v1/contacts/getentitybyid

[Terrance]

There's possibly two issues at play here then -- the 401s I'm seeing are few and far between, and so far I've not seen it throw one more than once per original request.

[ewah]

We've (nyc) have got a ton of convos, so this might be a numbers game.

[tdryer]

As of today, I'm seeing these occasional errors too.

[fraenki]

This commit seems to fix this issue for me:
https://github.com/tulir/hangups/commit/74690c0b05cbb3e2eb20b24cf38d35a324256d4a
(It may be necessary to apply all 4 commits from this fork.)

[tdryer]

This commit seems to fix this issue for me:

That's adding retries as suggested above. I doubt that workaround will function for too long.

I captured the parameters from a failed hangups request and tried replying it via an external script, but I can't reproduce the error there. I did notice that intentionally breaking the authorization header generator causes the server to randomly alternate between two error messages, which suggests the problem is that Google are gradually rolling out a new version of their backend that's incompatible somehow.

[tdryer]

I found the problem. aiohttp quotes the value of the SAPISID cookie because it contains special characters. Google's old backend accepts quoted cookies, but their new one does not.

There is an open issue in aiohttp, so we'll need a workaround.

requests does not quote the value, which is why I couldn't reproduce the problem in the first script I wrote.

Using chat-pa.clients6.google.com appears to always route requests to the new backend, while clients6.google.com randomly picks between the old and new.

[tdryer]

Fixed in version 0.4.11.