Seemingly random authentication failures

mrmatt...@gmail.com

unread,

Aug 20, 2015, 9:15:45 PM8/20/15

to ASynK Users

Hi,
When I run my google to google sync on the command line it always works. But I run it every 15mins via cron, and probably once an hour or two the sync fails with an "Invalid Credentials" error. My credentials are on an NFS share, so I thought perhaps they weren't immediately available sometimes (pretty unlikely I know!), so I now do an ls -l ~/.asynk/ before the sync, but it makes no difference. The full error is below. I can't blame asynk, it works fine from the command line, I expect it must be something to do with my machine or network (but I run tons of stuff from cron that access the network and they never bomb out), so I'm just looking for a clue about why this would be happening. Thanks!
Matt

CRITICAL:root:Exception (Unauthorized - Server responded with: 401, <?xml version="1.0" encoding="UTF-8"?>
<errors xmlns="http://schemas.google.com/g/2005">
<error>
<domain>GData</domain>
<code>authError</code>
<location type="header">Authorization</location>
<internalReason>Invalid Credentials</internalReason>
</error>
</errors>
) while syncing profile heatherkjenkins2mrmattwilkins
[12:30:05.625 CRITICAL] Exception (Unauthorized - Server responded with: 401, <?xml version="1.0" encoding="UTF-8"?>
<errors xmlns="http://schemas.google.com/g/2005">
<error>
<domain>GData</domain>
<code>authError</code>
<location type="header">Authorization</location>
<internalReason>Invalid Credentials</internalReason>
</error>
</errors>
) while syncing profile heatherkjenkins2mrmattwilkins
CRITICAL:root:Traceback (most recent call last):
File "/usr/local/ASynK/asynk/asynk_core.py", line 396, in op_sync
result = sync.sync(self.get_sync_dir())
File "/usr/local/ASynK/asynk/sync.py", line 295, in sync
sl1, sl2 = self.prep_lists(dirn)
File "/usr/local/ASynK/asynk/sync.py", line 283, in prep_lists
return self._prep_lists_2_way(self.get_f1(), self.get_f2())
File "/usr/local/ASynK/asynk/sync.py", line 179, in _prep_lists_2_way
f2.prep_sync_lists(f1.get_dbid(), f2sl)
File "/usr/local/ASynK/asynk/folder_gc.py", line 118, in prep_sync_lists
newi = self.get_itemids(pname, destid)
File "/usr/local/ASynK/asynk/folder_gc.py", line 219, in get_itemids
self._refresh_contacts()
File "/usr/local/ASynK/asynk/folder_gc.py", line 550, in _refresh_contacts
feed = self._get_group_feed()
File "/usr/local/ASynK/asynk/folder_gc.py", line 629, in _get_group_feed
feed = self.get_gdc().GetContacts(q=query)
File "/usr/local/ASynK/lib/gdata/contacts/client.py", line 201, in get_contacts
desired_class=desired_class, **kwargs)
File "/usr/local/ASynK/lib/gdata/client.py", line 640, in get_feed
**kwargs)
File "/usr/local/ASynK/lib/gdata/client.py", line 307, in request
response, Unauthorized)
Unauthorized: Unauthorized - Server responded with: 401, <?xml version="1.0" encoding="UTF-8"?>
<errors xmlns="http://schemas.google.com/g/2005">
<error>
<domain>GData</domain>
<code>authError</code>
<location type="header">Authorization</location>
<internalReason>Invalid Credentials</internalReason>
</error>
</errors>

[12:30:05.627 CRITICAL] Traceback (most recent call last):
File "/usr/local/ASynK/asynk/asynk_core.py", line 396, in op_sync
result = sync.sync(self.get_sync_dir())
File "/usr/local/ASynK/asynk/sync.py", line 295, in sync
sl1, sl2 = self.prep_lists(dirn)
File "/usr/local/ASynK/asynk/sync.py", line 283, in prep_lists
return self._prep_lists_2_way(self.get_f1(), self.get_f2())
File "/usr/local/ASynK/asynk/sync.py", line 179, in _prep_lists_2_way
f2.prep_sync_lists(f1.get_dbid(), f2sl)
File "/usr/local/ASynK/asynk/folder_gc.py", line 118, in prep_sync_lists
newi = self.get_itemids(pname, destid)
File "/usr/local/ASynK/asynk/folder_gc.py", line 219, in get_itemids
self._refresh_contacts()
File "/usr/local/ASynK/asynk/folder_gc.py", line 550, in _refresh_contacts
feed = self._get_group_feed()
File "/usr/local/ASynK/asynk/folder_gc.py", line 629, in _get_group_feed
feed = self.get_gdc().GetContacts(q=query)
File "/usr/local/ASynK/lib/gdata/contacts/client.py", line 201, in get_contacts
desired_class=desired_class, **kwargs)
File "/usr/local/ASynK/lib/gdata/client.py", line 640, in get_feed
**kwargs)
File "/usr/local/ASynK/lib/gdata/client.py", line 307, in request
response, Unauthorized)
Unauthorized: Unauthorized - Server responded with: 401, <?xml version="1.0" encoding="UTF-8"?>
<errors xmlns="http://schemas.google.com/g/2005">
<error>
<domain>GData</domain>
<code>authError</code>
<location type="header">Authorization</location>
<internalReason>Invalid Credentials</internalReason>
</error>
</errors>

Sriram Karra

unread,

Aug 20, 2015, 10:58:46 PM8/20/15

to as...@googlegroups.com

How long does each of your runs take? Asynk is not designed to be "thread safe". One wild possibility could be the cron runs are getting into each other. Sounds very unlikely, but that is the best guess I can come up with.

--
You received this message because you are subscribed to the Google Groups "ASynK Users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to asynk+un...@googlegroups.com.
To post to this group, send an email to as...@googlegroups.com.
To view this discussion on the web, visit https://groups.google.com/d/msgid/asynk/d943a4c0-5347-459a-a14a-95bb3be765b9%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

Matt Wilkins

unread,

Aug 20, 2015, 11:01:53 PM8/20/15

to as...@googlegroups.com

Thanks for the quick response, they are pretty quick though, about 10s.

> You received this message because you are subscribed to a topic in the

> Google Groups "ASynK Users" group.

> To unsubscribe from this topic, visit
> https://groups.google.com/d/topic/asynk/JKtcmvOmC9c/unsubscribe.
> To unsubscribe from this group and all its topics, send an email to
> asynk+un...@googlegroups.com.
> To post to this group, send email to as...@googlegroups.com.

> To view this discussion on the web, visit

> https://groups.google.com/d/msgid/asynk/CAFkt3UO2qfcOV4qbm14ixqHcpkjfp9bfMb670gquzjEMWLmxXQ%40mail.gmail.com.

Sriram Karra

unread,

Aug 22, 2015, 1:04:12 PM8/22/15

to as...@googlegroups.com

On Fri, Aug 21, 2015 at 6:45 AM, <mrmatt...@gmail.com> wrote:

Hi,
When I run my google to google sync on the command line it always works. But I run it every 15mins via cron, and probably once an hour or two the sync fails with an "Invalid Credentials" error.

I have pushed some code to a new branch called gc_debug: https://github.com/skarra/ASynK/commit/ffaaecaab6906a8f20ad935cdbf65c8f74cd9c7d

That gives you a new debug flag you can enable in your ~/.asynk/config.py (config['db_config']['gc']['log'] = True)

Can you run your cron syncs with that additional logging enabled? It may give us a clue about what's going on. Note that it will dump the headers of your requests which will contain your oAuth bearer tokens.

Matt Wilkins

unread,

Aug 24, 2015, 4:28:05 AM8/24/15

to as...@googlegroups.com

Hi there,

OK, this is the stdout and stderr:

[20:00:01.620 INFO] Debug logging to file:
/home/m/mwilkins/.asynk/logs/asynk_logs.2015-08-24.20-00-01.620058
[20:00:01.622 INFO] Deleting log files older than 7 days, if any...
[20:00:02.125 INFO] Deleting log files older than 7 days, if any...done
[20:00:02.126 INFO] Attempting to log into Google...
[20:00:02.132 INFO] Using pre-fetched access_token...
[20:00:02.639 INFO] Attempting to log into Google...
[20:00:02.640 INFO] Using pre-fetched access_token...
[20:00:03.021 INFO] Last synk for profile
heatherkjenkins2mrmattwilkins was at: 2015-08-24T07:45:07.57Z
[20:00:04.894 INFO] Querying Google for status of Contact Entries...
[20:00:05.295 INFO] Response recieved from Google. Processing...
[20:00:05.296 INFO] No entries in feed.
[20:00:05.629 CRITICAL] Exception (Unauthorized - Server responded

with: 401, <?xml version="1.0" encoding="UTF-8"?>
<errors xmlns="http://schemas.google.com/g/2005">
<error>
<domain>GData</domain>
<code>authError</code>
<location type="header">Authorization</location>
<internalReason>Invalid Credentials</internalReason>
</error>
</errors>
) while syncing profile heatherkjenkins2mrmattwilkins

[20:00:05.637 CRITICAL] Traceback (most recent call last):

And this is the contents of the log file:

[20:00:01.622 DEBUG] Command line: "/usr/local/ASynK/asynk.py
--op=sync --name heatherkjenkins2mrmattwilkins"
[20:00:01.622 INFO] Deleting log files older than 7 days, if any...
[20:00:01.755 DEBUG] Deleting File: asynk_logs.2015-08-17.19-45-09.981921...
[20:00:02.103 DEBUG] Deleting File: asynk_logs.2015-08-17.19-45-01.762218...
[20:00:02.125 INFO] Deleting log files older than 7 days, if any...done
[20:00:02.125 DEBUG] PIMDB gc does not have email_domains.
[20:00:02.125 DEBUG] PIMDB gc does not have notes_map
[20:00:02.126 DEBUG] PIMDB gc does not have phones_map
[20:00:02.126 INFO] Attempting to log into Google...
[20:00:02.132 INFO] Using pre-fetched access_token...
[20:00:02.132 DEBUG] Getting Group List to populate folders...
[20:00:02.133 DEBUG] HTTP Request
method: GET
url: https://www.google.com/m8/feeds/groups/default/full
headers:
GData-Version: 3
Authorization: Bearer
ya29.2QGVPFwlumcdtiyV-USmISrebTq9IwAOaGe3jZ7xb2zK5c30v6XBKZ-ssjcGmSls9Uky5g
User-Agent: ASynK gdata-py/2.0.18
body sections:

[20:00:02.638 DEBUG] Processing Folder: System Group: My Contacts...
[20:00:02.638 DEBUG] Processing Folder: System Group: Friends...
[20:00:02.638 DEBUG] Processing Folder: System Group: Family...
[20:00:02.639 DEBUG] Processing Folder: System Group: Coworkers...
[20:00:02.639 DEBUG] Processing Folder: LLL_Meeting_Reminder...
[20:00:02.639 DEBUG] Processing Folder: LLL_Support_Group...
[20:00:02.639 DEBUG] Processing Folder: LLL_Play_Group...
[20:00:02.639 DEBUG] Processing Folder: Starred in Android...
[20:00:02.639 DEBUG] PIMDB gc does not have email_domains.
[20:00:02.639 DEBUG] PIMDB gc does not have notes_map
[20:00:02.639 DEBUG] PIMDB gc does not have phones_map
[20:00:02.639 INFO] Attempting to log into Google...
[20:00:02.640 INFO] Using pre-fetched access_token...
[20:00:02.641 DEBUG] Getting Group List to populate folders...
[20:00:02.641 DEBUG] HTTP Request
method: GET
url: https://www.google.com/m8/feeds/groups/default/full
headers:
GData-Version: 3
Authorization: Bearer
ya29.2QGAHF-bIoBLNbi2G2hdi_tihdcXyyaA7mGwgggMnKHQnhTrU2pQUVUxQdBEWW2gRbms_-A
User-Agent: ASynK gdata-py/2.0.18
body sections:

[20:00:03.019 DEBUG] Processing Folder: System Group: My Contacts...
[20:00:03.019 DEBUG] Processing Folder: System Group: Friends...
[20:00:03.019 DEBUG] Processing Folder: System Group: Family...
[20:00:03.019 DEBUG] Processing Folder: System Group: Coworkers...
[20:00:03.019 DEBUG] Processing Folder: Starred in Android...
[20:00:03.020 DEBUG] pimdbs : [<pimdb_gc.GCPIMDB object at
0x283d750>, <pimdb_gc.GCPIMDB object at 0x1f8c090>]
[20:00:03.020 DEBUG] pname : heatherkjenkins2mrmattwilkins
[20:00:03.020 DEBUG] fid1 :
http://www.google.com/m8/feeds/groups/heatherkjenkins%40gmail.com/base/6
[20:00:03.020 DEBUG] fid2 :
http://www.google.com/m8/feeds/groups/mrmattwilkins%40gmail.com/base/6
[20:00:03.020 DEBUG] db1id : gc
[20:00:03.020 DEBUG] db : <pimdb_gc.GCPIMDB object at 0x283d750>
[20:00:03.021 INFO] Last synk for profile
heatherkjenkins2mrmattwilkins was at: 2015-08-24T07:45:07.57Z
[20:00:03.022 DEBUG] HTTP Request
method: GET
url: https://www.google.com/m8/feeds/contacts/default/full?max-results=100000&showdeleted=false&group=http%3A%2F%2Fwww.google.com%2Fm8%2Ffeeds%2Fgroups%2Fheatherkjenkins%2540gmail.com%2Fbase%2F6
headers:
GData-Version: 3
Authorization: Bearer
ya29.2QGVPFwlumcdtiyV-USmISrebTq9IwAOaGe3jZ7xb2zK5c30v6XBKZ-ssjcGmSls9Uky5g
User-Agent: ASynK gdata-py/2.0.18
body sections:

[20:00:04.894 INFO] Querying Google for status of Contact Entries...
[20:00:04.894 DEBUG] HTTP Request
method: GET
url: https://www.google.com/m8/feeds/contacts/default/full?max-results=100000&showdeleted=false&group=http%3A%2F%2Fwww.google.com%2Fm8%2Ffeeds%2Fgroups%2Fheatherkjenkins%2540gmail.com%2Fbase%2F6&updated-min=2015-08-24T07%3A45%3A07.57Z
headers:
GData-Version: 3
Authorization: Bearer
ya29.2QGVPFwlumcdtiyV-USmISrebTq9IwAOaGe3jZ7xb2zK5c30v6XBKZ-ssjcGmSls9Uky5g
User-Agent: ASynK gdata-py/2.0.18
body sections:

[20:00:05.295 INFO] Response recieved from Google. Processing...
[20:00:05.296 INFO] No entries in feed.
[20:00:05.297 DEBUG] HTTP Request
method: GET
url: https://www.google.com/m8/feeds/contacts/default/full?max-results=100000&showdeleted=false&group=http%3A%2F%2Fwww.google.com%2Fm8%2Ffeeds%2Fgroups%2Fmrmattwilkins%2540gmail.com%2Fbase%2F6
headers:
GData-Version: 3
Authorization: Bearer
ya29.2QGAHF-bIoBLNbi2G2hdi_tihdcXyyaA7mGwgggMnKHQnhTrU2pQUVUxQdBEWW2gRbms_-A
User-Agent: ASynK gdata-py/2.0.18
body sections:

[20:00:05.629 CRITICAL] Exception (Unauthorized - Server responded

with: 401, <?xml version="1.0" encoding="UTF-8"?>
<errors xmlns="http://schemas.google.com/g/2005">
<error>
<domain>GData</domain>
<code>authError</code>
<location type="header">Authorization</location>
<internalReason>Invalid Credentials</internalReason>
</error>
</errors>
) while syncing profile heatherkjenkins2mrmattwilkins

[20:00:05.637 CRITICAL] Traceback (most recent call last):

> --
> You received this message because you are subscribed to a topic in the
> Google Groups "ASynK Users" group.
> To unsubscribe from this topic, visit
> https://groups.google.com/d/topic/asynk/JKtcmvOmC9c/unsubscribe.
> To unsubscribe from this group and all its topics, send an email to
> asynk+un...@googlegroups.com.
> To post to this group, send email to as...@googlegroups.com.
> To view this discussion on the web, visit

> https://groups.google.com/d/msgid/asynk/CAFkt3UNtZy0hmNMFn2Zc1d3F5j-WnCuQviUksweUEHQyitSc1g%40mail.gmail.com.

Sriram Karra

unread,

Aug 24, 2015, 4:49:54 AM8/24/15

to as...@googlegroups.com

Can you send a similar log from a normal run from your command line that succeeds?

--
You received this message because you are subscribed to the Google Groups "ASynK Users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to asynk+un...@googlegroups.com.
To post to this group, send an email to as...@googlegroups.com.
To view this discussion on the web, visit https://groups.google.com/d/msgid/asynk/CADH-zAchB20L1YtyqizFWA4ZQv6JK%2BtdKJ8t8dQqussdKEt-Dw%40mail.gmail.com.

Matt Wilkins

unread,

Aug 24, 2015, 5:34:58 AM8/24/15

to as...@googlegroups.com

Here is the log file for a successful sync

[21:00:02.109 DEBUG] Command line: "/usr/local/ASynK/asynk.py
--op=sync --name heatherkjenkins2mrmattwilkins"
[21:00:02.109 INFO] Deleting log files older than 7 days, if any...
[21:00:02.186 DEBUG] Deleting File: asynk_logs.2015-08-17.20-55-57.013585...
[21:00:02.278 DEBUG] Deleting File: asynk_logs.2015-08-17.20-56-17.939857...
[21:00:02.408 DEBUG] Deleting File: asynk_logs.2015-08-17.20-57-11.326492...
[21:00:02.486 DEBUG] Deleting File: asynk_logs.2015-08-17.20-45-10.463708...
[21:00:02.569 INFO] Deleting log files older than 7 days, if any...done
[21:00:02.570 DEBUG] PIMDB gc does not have email_domains.
[21:00:02.570 DEBUG] PIMDB gc does not have notes_map
[21:00:02.570 DEBUG] PIMDB gc does not have phones_map
[21:00:02.570 INFO] Attempting to log into Google...
[21:00:02.575 INFO] Using pre-fetched access_token...
[21:00:02.576 DEBUG] Getting Group List to populate folders...
[21:00:02.576 DEBUG] HTTP Request

method: GET
url: https://www.google.com/m8/feeds/groups/default/full
headers:
GData-Version: 3
Authorization: Bearer

ya29.2QEnMsG0dlz_fLwCgv8Z6084zuo_ZBtjUdDDmcB0QjTEeqS37VyDfUu5RiVUflIlS-K75w