Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Manipulating Zarr metadata with GCSFS is slow #112

Closed
mrocklin opened this issue Feb 12, 2018 · 39 comments
Closed

Manipulating Zarr metadata with GCSFS is slow #112

mrocklin opened this issue Feb 12, 2018 · 39 comments

Comments

@mrocklin
Copy link
Member

%%prun

import gcsfs
gcsmap = gcsfs.mapping.GCSMap('pangeo-data/newman-met-ensemble')
ds = xr.open_zarr(gcsmap)
         16527714 function calls (16527548 primitive calls) in 11.297 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
       77    5.832    0.076    9.341    0.121 core.py:439(ls)
 16250415    3.533    0.000    3.533    0.000 {method 'startswith' of 'str' objects}
       46    1.453    0.032    1.453    0.032 {built-in method _openssl.SSL_read}
        7    0.096    0.014    0.098    0.014 core.py:161(<listcomp>)
        1    0.059    0.059    0.082    0.082 core.py:475(<listcomp>)
    15405    0.015    0.000    0.069    0.000 _collections_abc.py:742(__iter__)
    14532    0.014    0.000    0.039    0.000 os.py:664(__getitem__)
      168    0.011    0.000    0.011    0.000 {built-in method posix.stat}
       42    0.011    0.000    0.011    0.000 {built-in method _openssl.SSL_write}
    28502    0.009    0.000    0.009    0.000 {method 'decode' of 'bytes' objects}
       84    0.009    0.000    0.076    0.001 request.py:2458(getproxies_environment)
    28392    0.009    0.000    0.018    0.000 os.py:746(decode)
    14532    0.008    0.000    0.015    0.000 os.py:742(encode)
       42    0.008    0.000    0.008    0.000 {method 'close' of 'select.epoll' objects}
    22817    0.007    0.000    0.011    0.000 {built-in method builtins.isinstance}
    14280    0.007    0.000    0.015    0.000 os.py:687(__iter__)
        7    0.007    0.001    0.013    0.002 core.py:131(<listcomp>)
     9522    0.006    0.000    0.006    0.000 core.py:131(<genexpr>)
    16264    0.006    0.000    0.006    0.000 {method 'encode' of 'str' objects}
    20061    0.004    0.000    0.004    0.000 {method 'lower' of 'str' objects}
     7357    0.003    0.000    0.003    0.000 {method 'split' of 'str' objects}
       42    0.003    0.000    0.003    0.000 {method 'register' of 'select.epoll' objects}
        1    0.003    0.003    0.089    0.089 storage.py:128(_listdir_from_keys)
      800    0.002    0.000    1.459    0.002 {method 'readline' of '_io.BufferedReader' objects}
       88    0.002    0.000    0.002    0.000 {built-in method _openssl.SSL_get_error}
      210    0.002    0.000    0.006    0.000 _collections_abc.py:824(update)
11908/11833    0.002    0.000    0.002    0.000 {built-in method builtins.len}
       42    0.002    0.000    0.006    0.000 feedparser.py:471(_parse_headers)
       42    0.002    0.000    1.519    0.036 connectionpool.py:322(_make_request)
      378    0.002    0.000    0.007    0.000 parse.py:359(urlparse)
     1115    0.002    0.000    0.004    0.000 abc.py:178(__instancecheck__)
       42    0.002    0.000    0.024    0.001 client.py:194(parse_headers)
      420    0.002    0.000    0.004    0.000 message.py:462(get)
       42    0.002    0.000    0.002    0.000 selectors.py:392(__init__)
      420    0.002    0.000    0.003    0.000 parse.py:392(urlsplit)
      294    0.002    0.000    0.003    0.000 client.py:1195(putheader)
  192/185    0.002    0.000    0.002    0.000 indexing.py:508(shape)
       84    0.002    0.000    0.013    0.000 feedparser.py:218(_parsegen)
       42    0.002    0.000    1.552    0.037 connectionpool.py:447(urlopen)
       42    0.002    0.000    1.593    0.038 sessions.py:589(send)
      966    0.002    0.000    0.002    0.000 parse.py:109(_coerce_args)
       42    0.002    0.000    0.003    0.000 client.py:1071(putrequest)
     1126    0.002    0.000    0.002    0.000 {method 'match' of '_sre.SRE_Pattern' objects}
     1442    0.002    0.000    0.002    0.000 _weakrefset.py:70(__contains__)
     1542    0.001    0.000    0.001    0.000 {built-in method builtins.hasattr}
       88    0.001    0.000    0.004    0.000 SSL.py:1417(_raise_ssl_error)
       42    0.001    0.000    0.001    0.000 {method 'poll' of 'select.epoll' objects}
       46    0.001    0.000    1.456    0.032 SSL.py:1598(recv_into)
      714    0.001    0.000    0.003    0.000 _policybase.py:293(header_source_parse)
       42    0.001    0.000    1.485    0.035 client.py:290(begin)
       42    0.001    0.000    0.002    0.000 makefile.py:14(backport_makefile)
       42    0.001    0.000    0.038    0.001 sessions.py:401(prepare_request)
       42    0.001    0.000    0.025    0.001 client.py:1241(_send_request)
      294    0.001    0.000    0.008    0.000 sessions.py:50(merge_setting)
     1176    0.001    0.000    0.001    0.000 structures.py:48(__setitem__)
       42    0.001    0.000    1.581    0.038 adapters.py:388(send)
       72    0.001    0.000    9.343    0.130 core.py:537(info)
       42    0.001    0.000    1.720    0.041 core.py:983(_fetch)
      840    0.001    0.000    0.001    0.000 _collections.py:150(__getitem__)
        1    0.001    0.001   11.298   11.298 <string>:3(<module>)
      294    0.001    0.000    0.003    0.000 utils.py:244(to_key_val_list)
        7    0.001    0.000    0.113    0.016 core.py:135(getem)
       84    0.001    0.000    0.001    0.000 {method 'read' of '_io.StringIO' objects}
       84    0.001    0.000    0.003    0.000 posixpath.py:230(expanduser)
     1934    0.001    0.000    0.001    0.000 mapping.py:79(<genexpr>)
       21    0.001    0.000    0.003    0.000 core.py:1875(normalize_chunks)
      422    0.001    0.000    0.002    0.000 _collections_abc.py:657(get)
      168    0.001    0.000    0.002    0.000 message.py:497(get_all)
       42    0.001    0.000    1.714    0.041 sessions.py:441(request)
      924    0.001    0.000    0.002    0.000 _policybase.py:281(_sanitize_header)
      840    0.001    0.000    0.001    0.000 feedparser.py:78(readline)
       42    0.001    0.000    0.001    0.000 poolmanager.py:57(_default_key_normalizer)
       42    0.001    0.000    0.010    0.000 utils.py:160(get_netrc_auth)
     1008    0.001    0.000    0.001    0.000 structures.py:53(__getitem__)
       42    0.001    0.000    1.719    0.041 core.py:1082(_fetch_range)
       42    0.001    0.000    1.458    0.035 client.py:257(_read_status)
       42    0.001    0.000    1.717    0.041 requests.py:181(request)
       42    0.001    0.000    0.018    0.000 wait.py:9(_wait_for_io_events)
      617    0.001    0.000    0.001    0.000 {built-in method builtins.getattr}
     3498    0.001    0.000    0.001    0.000 {method 'append' of 'list' objects}
        5    0.001    0.000    0.796    0.159 core.py:1538(_chunk_getitem)
      714    0.001    0.000    0.002    0.000 _collections.py:208(add)
       42    0.001    0.000    0.003    0.000 models.py:588(__init__)
       42    0.001    0.000    0.004    0.000 models.py:433(prepare_headers)
       42    0.001    0.000    0.005    0.000 models.py:347(prepare_url)
       42    0.001    0.000    0.002    0.000 response.py:113(__init__)
       73    0.001    0.000    0.001    0.000 util.py:271(normalize_storage_path)
       84    0.001    0.000    0.003    0.000 cookiejar.py:1657(extract_cookies)
       42    0.001    0.000    0.012    0.000 adapters.py:253(build_response)
       42    0.001    0.000    0.010    0.000 response.py:441(from_httplib)
      126    0.001    0.000    0.002    0.000 cookiejar.py:1239(__init__)
      840    0.001    0.000    0.002    0.000 feedparser.py:128(__next__)
       42    0.001    0.000    6.785    0.162 mapping.py:64(__getitem__)
      168    0.001    0.000    0.006    0.000 structures.py:42(__init__)
       42    0.001    0.000    0.001    0.000 feedparser.py:139(__init__)
       84    0.001    0.000    0.001    0.000 {method 'readlines' of '_io._IOBase' objects}
       42    0.001    0.000    0.015    0.000 SSL.py:1516(send)
       84    0.001    0.000    0.003    0.000 utils.py:698(select_proxy)
        2    0.001    0.000    0.002    0.001 _pslinux.py:1555(memory_info)
       42    0.001    0.000    5.063    0.121 core.py:728(__init__)
       84    0.001    0.000    0.001    0.000 hooks.py:17(default_hooks)
       84    0.001    0.000    0.002    0.000 url.py:132(parse_url)
       25    0.001    0.000    3.954    0.158 core.py:105(__init__)
       42    0.001    0.000    0.005    0.000 response.py:346(read)
      824    0.001    0.000    0.001    0.000 {method 'get' of 'dict' objects}
       42    0.001    0.000    0.003    0.000 _collections.py:224(extend)
       42    0.001    0.000    0.042    0.001 utils.py:629(should_bypass_proxies)
     1234    0.001    0.000    0.001    0.000 {method 'find' of 'str' objects}
       42    0.001    0.000    1.488    0.035 client.py:1287(getresponse)
       42    0.001    0.000    0.001    0.000 {method 'settimeout' of '_socket.socket' objects}
      714    0.001    0.000    0.001    0.000 {method 'setdefault' of 'collections.OrderedDict' objects}

Something similar to this gets felt by the first read on every machine. This make the cluster feel like it's hanging for 20s or so. Somewhat reproducible with the following:

%%time
import pickle
b = pickle.dumps(gcsmap)
gcsmap2 = pickle.loads(b)
Wall time: 111 ms  # decent enough
%%prun 
len(gcsmap2)
     1230874 function calls (1182219 primitive calls) in 19.923 seconds

   Ordered by: internal time

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
    12768   17.324    0.001   17.324    0.001 {built-in method _openssl.SSL_read}
      109    0.823    0.008    0.829    0.008 decoder.py:345(raw_decode)
        1    0.132    0.132   19.834   19.834 core.py:378(_list_bucket)
    12768    0.103    0.000   17.536    0.001 SSL.py:1598(recv_into)
     9496    0.083    0.000    1.039    0.000 response.py:346(read)
        1    0.065    0.065    0.088    0.088 core.py:475(<listcomp>)
    12876    0.061    0.000    0.091    0.000 SSL.py:1417(_raise_ssl_error)
     9496    0.042    0.000    0.773    0.000 client.py:438(read)
     9496    0.039    0.000    0.676    0.000 {method 'readinto' of '_io.BufferedReader' objects}
    37714    0.039    0.000    0.104    0.000 os.py:664(__getitem__)
    12770    0.038    0.000   17.651    0.001 socket.py:572(readinto)
    39567    0.037    0.000    0.181    0.000 _collections_abc.py:742(__iter__)
     9496    0.032    0.000    0.713    0.000 client.py:470(readinto)
      989    0.030    0.000    1.103    0.001 {method 'join' of 'bytes' objects}
    12768    0.029    0.000   17.565    0.001 pyopenssl.py:278(recv_into)
        2    0.028    0.014    0.028    0.014 {built-in method _socket.getaddrinfo}
     9605    0.027    0.000    0.060    0.000 contextlib.py:85(__exit__)
      432    0.026    0.000    0.026    0.000 {built-in method posix.stat}
    12770    0.025    0.000    0.025    0.000 {method '_checkClosed' of '_io._IOBase' objects}
    74369    0.025    0.000    0.025    0.000 {method 'decode' of 'bytes' objects}
   108491    0.025    0.000    0.025    0.000 {method 'startswith' of 'str' objects}
    10477    0.024    0.000    0.047    0.000 _collections_abc.py:657(get)
    73684    0.023    0.000    0.047    0.000 os.py:746(decode)
      218    0.023    0.000    0.200    0.001 request.py:2458(getproxies_environment)
     9496    0.022    0.000    0.065    0.000 response.py:250(_init_decoder)
    37714    0.022    0.000    0.041    0.000 os.py:742(encode)
   108380    0.021    0.000    0.021    0.000 {method 'get' of 'dict' objects}
    12876    0.021    0.000    0.021    0.000 {built-in method _openssl.SSL_get_error}
      107    0.020    0.000    0.020    0.000 {built-in method time.sleep}
     9605    0.019    0.000    0.025    0.000 contextlib.py:59(__init__)
    37060    0.018    0.000    0.041    0.000 os.py:687(__iter__)
     9605    0.018    0.000    1.066    0.000 response.py:415(stream)
    18992    0.018    0.000    0.027    0.000 response.py:289(_error_catcher)
    12768    0.018    0.000    0.018    0.000 {built-in method allocator}
     9496    0.017    0.000    0.017    0.000 {method 'tobytes' of 'memoryview' objects}
    10694    0.017    0.000    0.022    0.000 _collections.py:150(__getitem__)
      107    0.017    0.000    0.017    0.000 {built-in method _openssl.SSL_write}
    56502    0.016    0.000    0.025    0.000 {built-in method builtins.isinstance}
    41998    0.016    0.000    0.016    0.000 {method 'encode' of 'str' objects}
      107    0.016    0.000    0.016    0.000 models.py:830(text)
    59955    0.015    0.000    0.015    0.000 {method 'lower' of 'str' objects}
     9605    0.013    0.000    0.038    0.000 contextlib.py:157(helper)
    19210    0.013    0.000    0.040    0.000 {built-in method builtins.next}
  48656/1    0.013    0.000   19.924   19.924 {built-in method builtins.len}
    12879    0.012    0.000    0.012    0.000 socket.py:611(readable)
    12770    0.011    0.000    0.022    0.000 {method '_checkReadable' of '_io._IOBase' objects}
      107    0.008    0.000    0.008    0.000 {method 'close' of 'select.epoll' objects}
    12876    0.008    0.000    0.008    0.000 SSL.py:199(raise_if_problem)
    10926    0.008    0.000    0.008    0.000 {built-in method builtins.getattr}
     9605    0.007    0.000    1.073    0.000 models.py:741(generate)
        1    0.007    0.007    0.007    0.007 {built-in method _openssl.SSL_CTX_load_verify_locations}
     9605    0.006    0.000    0.009    0.000 response.py:7(is_fp_closed)
    19317    0.006    0.000    0.006    0.000 client.py:428(isclosed)
     2628    0.006    0.000    0.009    0.000 abc.py:178(__instancecheck__)
     1198    0.006    0.000   17.020    0.014 {method 'readline' of '_io.BufferedReader' objects}
     1102    0.006    0.000    0.010    0.000 parse.py:392(urlsplit)
     9496    0.005    0.000    0.005    0.000 response.py:260(_decode)
     9605    0.005    0.000    0.013    0.000 contextlib.py:79(__enter__)
      993    0.005    0.000    0.020    0.000 parse.py:359(urlparse)
      218    0.005    0.000    0.033    0.000 feedparser.py:218(_parsegen)
     1960    0.005    0.000    0.005    0.000 {method 'match' of '_sre.SRE_Pattern' objects}
     2555    0.005    0.000    0.006    0.000 parse.py:109(_coerce_args)
      109    0.005    0.000    0.064    0.001 client.py:194(parse_headers)
      107    0.005    0.000   19.679    0.184 core.py:340(_call)
      109    0.005    0.000   17.202    0.158 connectionpool.py:322(_make_request)
      109    0.005    0.000    0.012    0.000 feedparser.py:471(_parse_headers)
      549    0.005    0.000    0.012    0.000 _collections_abc.py:824(update)
      109    0.005    0.000   18.461    0.169 sessions.py:589(send)
      109    0.005    0.000   17.266    0.158 connectionpool.py:447(urlopen)
      109    0.004    0.000   17.093    0.157 client.py:290(begin)
      654    0.004    0.000    0.008    0.000 client.py:1195(putheader)
      109    0.004    0.000    0.008    0.000 client.py:1071(putrequest)
     1090    0.004    0.000    0.008    0.000 message.py:462(get)
      107    0.004    0.000    0.004    0.000 selectors.py:392(__init__)
     3393    0.004    0.000    0.004    0.000 _weakrefset.py:70(__contains__)
      109    0.004    0.000   17.021    0.156 client.py:257(_read_status)
      107    0.004    0.000    0.005    0.000 makefile.py:14(backport_makefile)
      292    0.004    0.000    0.005    0.000 utils_perf.py:178(_gc_callback)
      107    0.003    0.000   18.798    0.176 requests.py:181(request)
      109    0.003    0.000   17.343    0.159 adapters.py:388(send)
      763    0.003    0.000    0.022    0.000 sessions.py:50(merge_setting)
      109    0.003    0.000   18.790    0.172 sessions.py:441(request)
     3491    0.003    0.000    0.003    0.000 {built-in method builtins.hasattr}
      109    0.003    0.000    0.108    0.001 sessions.py:401(prepare_request)
      325    0.003    0.000    0.003    0.000 {method 'extend' of 'list' objects}
      109    0.003    0.000    0.061    0.001 client.py:1241(_send_request)
      763    0.003    0.000    0.009    0.000 utils.py:244(to_key_val_list)
      109    0.003    0.000    0.005    0.000 feedparser.py:139(__init__)
      107    0.003    0.000    0.003    0.000 {method 'register' of 'select.epoll' objects}
     2202    0.003    0.000    0.003    0.000 {method 'split' of 'str' objects}
      109    0.003    0.000    0.003    0.000 poolmanager.py:57(_default_key_normalizer)
      109    0.003    0.000    0.025    0.000 models.py:347(prepare_url)
      978    0.002    0.000    0.005    0.000 _policybase.py:293(header_source_parse)
      219    0.002    0.000    0.007    0.000 posixpath.py:230(expanduser)
      109    0.002    0.000    0.009    0.000 models.py:588(__init__)
      109    0.002    0.000    0.023    0.000 utils.py:160(get_netrc_auth)
      327    0.002    0.000    0.004    0.000 cookiejar.py:1239(__init__)
        1    0.002    0.002    0.002    0.002 {built-in method _openssl.SSL_do_handshake}
      109    0.002    0.000    0.031    0.000 adapters.py:253(build_response)
@mrocklin
Copy link
Member Author

cc @martindurant @jhamman

@mrocklin
Copy link
Member Author

Here is a profile output suitable for snakeviz

len-gcsmap.prof.gz

@jhamman
Copy link
Member

jhamman commented Feb 12, 2018

@mrocklin - are you still using xarray@master and zarr@master?

@mrocklin
Copy link
Member Author

mrocklin commented Feb 12, 2018 via email

@mrocklin
Copy link
Member Author

This is from my local machine:

In [1]: import gcsfs

In [2]: %time gcsmap = gcsfs.mapping.GCSMap('pangeo-data/newman-met-ensemble')
CPU times: user 4.45 s, sys: 1.39 s, total: 5.84 s
Wall time: 47 s

In [3]: %time len(gcsmap)
CPU times: user 117 ms, sys: 4.39 ms, total: 121 ms
Wall time: 122 ms
Out[3]: 1933

In [4]: import pickle

In [5]: %time b = pickle.dumps(gcsmap)
CPU times: user 484 µs, sys: 114 µs, total: 598 µs
Wall time: 609 µs

In [6]: len(b)
Out[6]: 2047

In [7]: %time pickle.loads(b) 
CPU times: user 0 ns, sys: 3.75 ms, total: 3.75 ms
Wall time: 3.01 s
Out[7]: <gcsfs.mapping.GCSMap at 0x7f1f8c1a9400>

The 3s when calling pickle.loads is in connect and it's 3.00s exactly. Perhaps some sort of timeout?

@martindurant
Copy link
Contributor

I guess this is calling info() a lot, which is not using cached information.

If I recall, we specifically made pickling of the gcsfs object abandon its cached files listing, because it could use a lot of memory and take time to serialize.

If you do info() on a specific file that is not in the cache, it calls HEAD on the server, without doing a file listing (which is somewhat generally slower, but only gets done once for the whole directory). Maybe when we switch to prefix/delimited file listing, we should get rid of the direct route for info, which was only ever present to deal with buckets like this that have many many files overall.

@martindurant
Copy link
Contributor

In [7]: %time pickle.loads(b) 
CPU times: user 0 ns, sys: 3.75 ms, total: 3.75 ms
Wall time: 3.01 s
Out[7]: <gcsfs.mapping.GCSMap at 0x7f1f8c1a9400>

Connecting can be slow the first time per worker, as the various credentials are tried by google. It may be faster to provide a concrete token, if available, or specify token='cloud' like before.

Are we making use of the current() method of GCSFileSystem?

@rabernat
Copy link
Member

Connecting can be slow the first time per worker

In my experience (#117), the slow "first time" has to be repeated for every computation. So if i do

vp = ds.somevar.mean().persist()
del vp
vp = ds.somevar.mean().persist()

I am faced with the extra overhead (presumably each worker connecting to gcs) twice, or more generally, every time I make a calculation. This is something I would really like to avoid.

Any thoughts on the best way to work around this?

@martindurant
Copy link
Contributor

@mrocklin , is there a way we can verify that the gcsfs singleton is being found by the workers, rather than connecting afresh? It should keep hold of the dir entries too, to avoid many calls to info.

@mrocklin
Copy link
Member Author

I would probably ask you this question :)

Maybe maintain a global count somewhere of the number of connect calls, run a computation, and then check that number across all workers using client.run?

I think that @rabernat is more affected by 20s delays rather than 3s delays (correct me if I'm wrong) which I think puts the problem at listing files rather than connections.

@rabernat
Copy link
Member

When going to larger calculations and cluster sizes, 20s is becoming 60s or more. So it is a real bottleneck

@martindurant
Copy link
Contributor

The following diff seems to be useful for sharing state between like instances in different threads on the same worker:

--- a/gcsfs/core.py
+++ b/gcsfs/core.py
@@ -917,7 +917,14 @@ class GCSFileSystem(object):

     def __setstate__(self, state):
         self.__dict__.update(state)
-        self.connect(self.token)
+        if (self._singleton[0] is not None and
+                state['method'] in ['google_default', 'cloud', 'anon']):
+            self.__dict__.update(self._singleton[0].__dict__)
+        elif (self._singleton[0] is not None and state['method'] == 'cache' and
+              (project, access) in self.tokens):
+            self.__dict__.update(self._singleton[0].__dict__)
+        else:
+            self.connect(self.token)

I am not sure, @rabernat , if you are using any of the experimental code in fsspec/gcsfs#57 or fsspec/gcsfs#67, but that makes individual ls operations much faster for big buckets, at the cost of needing more calls for deeply nested directory structures; it likely helps for your situation. Getting that code production-ready will take a little effort yet.

A small thing to also try: do you see any better performance with

gcs = gcsfs.GCSFileSystem(token='cloud')
gcsmap = gcsfs.mapping.GCSMap('pangeo-data/newman-met-ensemble', gcs=gcs)

@mrocklin
Copy link
Member Author

The docker containers are currently running on git-master as of three days ago.

@rabernat if you wanted to try out other versions you would both pip install locally and also include env={'EXTRA_PIP_PACKAGES': 'git+...'} in your KubeCluster call.

@rabernat
Copy link
Member

@martindurant - using gcs = gcsfs.GCSFileSystem(token='cloud') had no noticeable effect on performance.

I'll see if I can find the time to check out one of these branches.

@asford
Copy link

asford commented Feb 14, 2018

I'm using fsspec/gcsfs#57 for production runs in a setup that's somewhat similar to yours. Our data buckets, for example, contain 10e5 to 10e6 objects and the global bucket caching approach simply doesn't work.

I've been pushing in-progress commits over the last several days for testing, but if you'd like to test it I can stabilize it.

@rabernat
Copy link
Member

@asford - Thanks! I'm curious to try your fix. Let me know when you think it is in a state I can use.

@rabernat
Copy link
Member

rabernat commented Feb 16, 2018

fsspec/gcsfs#57 did not have any noticeable effect on performance. Still taking about 20s of communication to get each worker going. 😢

@asford
Copy link

asford commented Feb 16, 2018

ed: Specifically referring to fsspec/gcsfs#57

Do you have a reasonably easy repro case of this slowdown? Would it be possible for to run one with the gcsfs.core and gcsfs.gcsfuse loggers at the logging.DEBUG level? That will produce a lot of tracing, but could be useful to track down where this perf issue is coming from.

@rabernat
Copy link
Member

@asford, assuming you can access our pangeo storage buckets (if not, send me your google account username and I will grant you access), you can run this to reproduce the issue. This is exactly what I'm doing via http://pangeo.pydata.org.

I have already run

! pip install --upgrade --user git+https://github.com/asford/gcsfs.git@per_dir_cache

from my notebook.

from dask.distributed import Client
from daskernetes import KubeCluster
import xarray as xr
import gcsfs

# do I need an --upgrade flag here?
cluster = KubeCluster(n_workers=20, 
                      env={'EXTRA_PIP_PACKAGES': 'git+https://github.com/asford/gcsfs.git@per_dir_cache'})
client = Client(cluster)

# (token='cloud') doesn't work with experimental branch
gcs = gcsfs.GCSFileSystem()
gcsmap = gcsfs.mapping.GCSMap('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt', gcs=gcs)
# from the notebook this is quite fast, just a few s
ds = xr.open_zarr(gcsmap)

# compute something
sla_timeseries = ds.sla.mean(dim=('latitude', 'longitude')).persist()

How do I know if EXTRA_PIP_PACKAGES is working on the workers? Within the notebook, I need an --upgrade flag to make sure the branch version is actually installed. It seems like I would need something similar on the workers.

If you tell me how to enable the gcsfs loggers I can try to do it.

@asford
Copy link

asford commented Feb 16, 2018

In a basic case you can use:

import logging
logging.basicConfig(
    format="%(created)0.3f %(levelname)s %(name)s %(message)s",
    level=logging.INFO)
logging.getLogger("gcsfs.core").setLevel(logging.DEBUG)
logging.getLogger("gcsfs.gcsfs").setLevel(logging.DEBUG)

To enable logging on the channels.

I'm sorry, but I don't have sufficient experience using daskernetes or that environment to help with ensuring that you've the correct variant branch installed. However I would be happy to look through the gcsfs logs if @mrocklin or @martindurant can help you get a repro. It would be ideal if you could pull logs from both the client and worker nodes.

@rabernat
Copy link
Member

rabernat commented Feb 16, 2018

Below is a tiny subset of the logging information that came out on the client. (Edit: this happens when I call open_zarr.)

1518772138.566 DEBUG gcsfs.core exists(args=('pangeo-data',), kwargs={})
1518772138.569 DEBUG gcsfs.core _list_buckets
1518772138.570 DEBUG gcsfs.core _call(get, b/, args=(), kwargs={'project': 'pangeo-181919'})
1518772138.698 DEBUG gcsfs.core _list_buckets result: {'items': 4}
1518772138.728 DEBUG gcsfs.core exists(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zarray',), kwargs={})
1518772138.729 DEBUG gcsfs.core info(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zarray',), kwargs={})
1518772138.730 DEBUG gcsfs.core _get_object(pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zarray)
1518772138.732 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/',), kwargs={})
1518772138.733 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/
1518772138.734 DEBUG gcsfs.core _call(get, b/{}/o/{}, args=('pangeo-data', 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zarray'), kwargs={})
1518772138.775 DEBUG gcsfs.core info FileNotFound at path: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zarray
1518772138.776 DEBUG gcsfs.core ls(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt', True), kwargs={})
1518772138.778 DEBUG gcsfs.core _list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt',), kwargs={})
1518772138.779 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt',), kwargs={})
1518772138.780 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt
1518772138.781 DEBUG gcsfs.core _do_list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt', None), kwargs={})
1518772138.782 DEBUG gcsfs.core _call(get, b/{}/o/, args=('pangeo-data',), kwargs={'delimiter': '/', 'prefix': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt', 'maxResults': None})
1518772138.831 DEBUG gcsfs.core _list_objects result: {'prefixes': 1, 'items': 0}
1518772138.832 DEBUG gcsfs.core _list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/',), kwargs={})
1518772138.834 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/',), kwargs={})
1518772138.836 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/
1518772138.837 DEBUG gcsfs.core _do_list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/', None), kwargs={})
1518772138.838 DEBUG gcsfs.core _call(get, b/{}/o/, args=('pangeo-data',), kwargs={'delimiter': '/', 'prefix': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/', 'maxResults': None})
1518772138.997 DEBUG gcsfs.core _list_objects result: {'prefixes': 14, 'items': 2}
1518772138.999 DEBUG gcsfs.core exists(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zgroup',), kwargs={})
1518772139.000 DEBUG gcsfs.core info(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zgroup',), kwargs={})
1518772139.001 DEBUG gcsfs.core _get_object(pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zgroup)
1518772139.002 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/',), kwargs={})
1518772139.003 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/
1518772139.004 DEBUG gcsfs.core found cached object: [{'kind': 'storage#object', 'id': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zgroup/1517251222477719', 'selfLink': 'https://www.googleapis.com/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2F.zgroup', 'name': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zgroup', 'bucket': 'pangeo-data', 'generation': '1517251222477719', 'metageneration': '1', 'timeCreated': '2018-01-29T18:40:22.456Z', 'updated': '2018-01-29T18:40:22.456Z', 'storageClass': 'REGIONAL', 'timeStorageClassUpdated': '2018-01-29T18:40:22.456Z', 'size': 24, 'md5Hash': '4gKXk15z3QFUEE1OpTBAqw==', 'mediaLink': 'https://www.googleapis.com/download/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2F.zgroup?generation=1517251222477719&alt=media', 'crc32c': 'REp3Bw==', 'etag': 'CJe3mqHp/dgCEAE=', 'path': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zgroup'}]
1518772139.005 DEBUG gcsfs.core exists(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zarray',), kwargs={})
1518772139.006 DEBUG gcsfs.core info(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zarray',), kwargs={})
1518772139.007 DEBUG gcsfs.core _get_object(pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zarray)
1518772139.008 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/',), kwargs={})
1518772139.008 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/
1518772139.009 DEBUG gcsfs.core _call(get, b/{}/o/{}, args=('pangeo-data', 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zarray'), kwargs={})
1518772139.039 DEBUG gcsfs.core info FileNotFound at path: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zarray
1518772139.040 DEBUG gcsfs.core ls(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt', True), kwargs={})
1518772139.042 DEBUG gcsfs.core _list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt',), kwargs={})
1518772139.043 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt',), kwargs={})
1518772139.043 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt
1518772139.044 DEBUG gcsfs.core _list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/',), kwargs={})
1518772139.045 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/',), kwargs={})
1518772139.046 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/
1518772139.047 DEBUG gcsfs.core open(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zgroup', 'rb', None, None, None, None), kwargs={})
1518772139.048 DEBUG gcsfs.core __init__(args=(<gcsfs.core.GCSFileSystem object at 0x7f8d67f895c0>, 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zgroup', 'rb', 5242880, None, 'none', None), kwargs={})
1518772139.049 DEBUG gcsfs.core info(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zgroup',), kwargs={})
1518772139.050 DEBUG gcsfs.core _get_object(pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zgroup)
1518772139.051 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/',), kwargs={})
1518772139.051 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/
1518772139.052 DEBUG gcsfs.core found cached object: [{'kind': 'storage#object', 'id': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zgroup/1517251222477719', 'selfLink': 'https://www.googleapis.com/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2F.zgroup', 'name': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zgroup', 'bucket': 'pangeo-data', 'generation': '1517251222477719', 'metageneration': '1', 'timeCreated': '2018-01-29T18:40:22.456Z', 'updated': '2018-01-29T18:40:22.456Z', 'storageClass': 'REGIONAL', 'timeStorageClassUpdated': '2018-01-29T18:40:22.456Z', 'size': 24, 'md5Hash': '4gKXk15z3QFUEE1OpTBAqw==', 'mediaLink': 'https://www.googleapis.com/download/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2F.zgroup?generation=1517251222477719&alt=media', 'crc32c': 'REp3Bw==', 'etag': 'CJe3mqHp/dgCEAE=', 'path': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zgroup'}]
1518772139.053 DEBUG gcsfs.core __enter__(args=(), kwargs={})
1518772139.054 DEBUG gcsfs.core _fetch(args=(0, 24), kwargs={})
--- Logging error ---
Traceback (most recent call last):
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 992, in emit
    msg = self.format(record)
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 838, in format
    return fmt.format(record)
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 575, in format
    record.message = record.getMessage()
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 338, in getMessage
    msg = msg % self.args
TypeError: not all arguments converted during string formatting
Call stack:
  File "/opt/conda/lib/python3.6/runpy.py", line 193, in _run_module_as_main
    "__main__", mod_spec)
  File "/opt/conda/lib/python3.6/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/__main__.py", line 3, in <module>
    app.launch_new_instance()
  File "/opt/conda/lib/python3.6/site-packages/traitlets/config/application.py", line 658, in launch_instance
    app.start()
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelapp.py", line 477, in start
    ioloop.IOLoop.instance().start()
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/ioloop.py", line 177, in start
    super(ZMQIOLoop, self).start()
  File "/opt/conda/lib/python3.6/site-packages/tornado/ioloop.py", line 888, in start
    handler_func(fd_obj, events)
  File "/opt/conda/lib/python3.6/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    return fn(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 440, in _handle_events
    self._handle_recv()
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 472, in _handle_recv
    self._run_callback(callback, msg)
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 414, in _run_callback
    callback(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    return fn(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 283, in dispatcher
    return self.dispatch_shell(stream, msg)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 235, in dispatch_shell
    handler(stream, idents, msg)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 399, in execute_request
    user_expressions, allow_stdin)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/ipkernel.py", line 196, in do_execute
    res = shell.run_cell(code, store_history=store_history, silent=silent)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/zmqshell.py", line 533, in run_cell
    return super(ZMQInteractiveShell, self).run_cell(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2728, in run_cell
    interactivity=interactivity, compiler=compiler, result=result)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2850, in run_ast_nodes
    if self.run_code(code, result):
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2910, in run_code
    exec(code_obj, self.user_global_ns, self.user_ns)
  File "<ipython-input-9-051a91e550af>", line 5, in <module>
    get_ipython().run_line_magic('time', 'ds = xr.open_zarr(gcsmap)')
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2095, in run_line_magic
    result = fn(*args,**kwargs)
  File "<decorator-gen-62>", line 2, in time
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/magic.py", line 187, in <lambda>
    call = lambda f, *a, **k: f(*a, **k)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/magics/execution.py", line 1238, in time
    exec(code, glob, local_ns)
  File "<timed exec>", line 1, in <module>
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 472, in open_zarr
    group=group)
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 278, in open_group
    synchronizer=synchronizer, path=group)
  File "/opt/conda/lib/python3.6/site-packages/zarr/hierarchy.py", line 1136, in open_group
    synchronizer=synchronizer, path=path)
  File "/opt/conda/lib/python3.6/site-packages/zarr/hierarchy.py", line 112, in __init__
    meta_bytes = store[mkey]
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/mapping.py", line 68, in __getitem__
    result = f.read()
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1280, in read
    self._fetch(self.loc, self.loc + length)
  File "<decorator-gen-156>", line 2, in _fetch
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 48, in _tracemethod
    return f(self, *args, **kwargs)
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1239, in _fetch
    self.end)
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1344, in _fetch_range
    logger.debug("Fetch: {}, {}-{}", obj_dict['name'], start, end)
Message: 'Fetch: {}, {}-{}'
Arguments: ('dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zgroup', 0, 10485760)
1518772139.201 DEBUG gcsfs.core __exit__(args=(None, None, None), kwargs={})
1518772139.203 DEBUG gcsfs.core close(args=(), kwargs={})
1518772139.204 DEBUG gcsfs.core __del__(args=(), kwargs={})
1518772139.208 DEBUG gcsfs.core close(args=(), kwargs={})
1518772139.210 DEBUG gcsfs.core walk(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt', False), kwargs={})
1518772139.212 DEBUG gcsfs.core walk(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/', True), kwargs={})
1518772139.214 DEBUG gcsfs.core ls(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/', True), kwargs={})
1518772139.215 DEBUG gcsfs.core _list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/',), kwargs={})
1518772139.216 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/',), kwargs={})
1518772139.217 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/
1518772139.218 DEBUG gcsfs.core walk(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/', True), kwargs={})
1518772139.218 DEBUG gcsfs.core ls(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/', True), kwargs={})
1518772139.219 DEBUG gcsfs.core _list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/',), kwargs={})
1518772139.221 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/',), kwargs={})
1518772139.222 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/
1518772139.223 DEBUG gcsfs.core _do_list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/', None), kwargs={})
1518772139.224 DEBUG gcsfs.core _call(get, b/{}/o/, args=('pangeo-data',), kwargs={'delimiter': '/', 'prefix': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/', 'maxResults': None})
1518772139.458 DEBUG gcsfs.core _call(get, b/{}/o/, args=('pangeo-data',), kwargs={'delimiter': '/', 'prefix': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/', 'maxResults': None, 'pageToken': 'CkBkYXRhc2V0LWR1YWNzLXJlcC1nbG9iYWwtbWVyZ2VkLWFsbHNhdC1waHktbDQtdjMtYWx0L2FkdC8yOTMuMC4w'})
1518772139.632 DEBUG gcsfs.core _list_objects result: {'prefixes': 0, 'items': 1783}
1518772139.640 DEBUG gcsfs.core walk(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/', True), kwargs={})
1518772139.641 DEBUG gcsfs.core ls(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/', True), kwargs={})
1518772139.642 DEBUG gcsfs.core _list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/',), kwargs={})
1518772139.644 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/',), kwargs={})
1518772139.645 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/
1518772139.646 DEBUG gcsfs.core _do_list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/', None), kwargs={})
1518772139.647 DEBUG gcsfs.core _call(get, b/{}/o/, args=('pangeo-data',), kwargs={'delimiter': '/', 'prefix': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/', 'maxResults': None})
1518772139.684 DEBUG gcsfs.core _list_objects result: {'prefixes': 0, 'items': 3}
1518772139.685 DEBUG gcsfs.core walk(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/', True), kwargs={})
1518772139.686 DEBUG gcsfs.core ls(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/', True), kwargs={})
1518772139.688 DEBUG gcsfs.core _list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/',), kwargs={})
1518772139.689 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/',), kwargs={})
1518772139.690 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/
1518772139.691 DEBUG gcsfs.core _do_list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/', None), kwargs={})
1518772139.692 DEBUG gcsfs.core _call(get, b/{}/o/, args=('pangeo-data',), kwargs={'delimiter': '/', 'prefix': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/', 'maxResults': None})
1518772139.861 DEBUG gcsfs.core _call(get, b/{}/o/, args=('pangeo-data',), kwargs={'delimiter': '/', 'prefix': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/', 'maxResults': None, 'pageToken': 'CkBkYXRhc2V0LWR1YWNzLXJlcC1nbG9iYWwtbWVyZ2VkLWFsbHNhdC1waHktbDQtdjMtYWx0L2Vyci8yOTMuMC4w'})
1518772139.999 DEBUG gcsfs.core _list_objects result: {'prefixes': 0, 'items': 1783}
1518772140.008 DEBUG gcsfs.core walk(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/', True), kwargs={})
1518772140.009 DEBUG gcsfs.core ls(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/', True), kwargs={})
1518772140.010 DEBUG gcsfs.core _list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/',), kwargs={})
1518772140.012 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/',), kwargs={})
1518772140.013 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/
1518772140.013 DEBUG gcsfs.core _do_list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/', None), kwargs={})
1518772140.015 DEBUG gcsfs.core _call(get, b/{}/o/, args=('pangeo-data',), kwargs={'delimiter': '/', 'prefix': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/', 'maxResults': None})
1518772140.183 DEBUG gcsfs.core _call(get, b/{}/o/, args=('pangeo-data',), kwargs={'delimiter': '/', 'prefix': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/', 'maxResults': None, 'pageToken': 'CkVkYXRhc2V0LWR1YWNzLXJlcC1nbG9iYWwtbWVyZ2VkLWFsbHNhdC1waHktbDQtdjMtYWx0L2xhdF9ibmRzLzI5My4wLjA='})
1518772140.322 DEBUG gcsfs.core _list_objects result: {'prefixes': 0, 'items': 1783}
1518772140.330 DEBUG gcsfs.core walk(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/', True), kwargs={})
1518772140.332 DEBUG gcsfs.core ls(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/', True), kwargs={})
1518772140.333 DEBUG gcsfs.core _list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/',), kwargs={})
1518772140.334 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/',), kwargs={})
1518772140.334 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/
1518772140.335 DEBUG gcsfs.core _do_list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/', None), kwargs={})
1518772140.336 DEBUG gcsfs.core _call(get, b/{}/o/, args=('pangeo-data',), kwargs={'delimiter': '/', 'prefix': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/', 'maxResults': None})
1518772140.377 DEBUG gcsfs.core _list_objects result: {'prefixes': 0, 'items': 3}
1518772140.380 DEBUG gcsfs.core walk(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lon_bnds/', True), kwargs={})
1518772140.381 DEBUG gcsfs.core ls(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lon_bnds/', True), kwargs={})
1518772140.382 DEBUG gcsfs.core _list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lon_bnds/',), kwargs={})
1518772140.383 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lon_bnds/',), kwargs={})
1518772140.384 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lon_bnds/
1518772140.385 DEBUG gcsfs.core _do_list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lon_bnds/', None), kwargs={})
1518772140.386 DEBUG gcsfs.core _call(get, b/{}/o/, args=('pangeo-data',), kwargs={'delimiter': '/', 'prefix': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lon_bnds/', 'maxResults': None})
1518772140.420 DEBUG gcsfs.core _list_objects result: {'prefixes': 0, 'items': 3}
1518772140.422 DEBUG gcsfs.core walk(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/longitude/', True), kwargs={})
1518772140.424 DEBUG gcsfs.core ls(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/longitude/', True), kwargs={})
1518772140.424 DEBUG gcsfs.core _list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/longitude/',), kwargs={})
1518772140.425 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/longitude/',), kwargs={})
1518772140.426 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/longitude/
1518772140.427 DEBUG gcsfs.core _do_list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/longitude/', None), kwargs={})
1518772140.428 DEBUG gcsfs.core _call(get, b/{}/o/, args=('pangeo-data',), kwargs={'delimiter': '/', 'prefix': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/longitude/', 'maxResults': None})
1518772140.469 DEBUG gcsfs.core _list_objects result: {'prefixes': 0, 'items': 3}
1518772140.472 DEBUG gcsfs.core walk(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/nv/', True), kwargs={})
1518772140.473 DEBUG gcsfs.core ls(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/nv/', True), kwargs={})
1518772140.474 DEBUG gcsfs.core _list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/nv/',), kwargs={})
1518772140.475 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/nv/',), kwargs={})
1518772140.475 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/nv/
1518772140.476 DEBUG gcsfs.core _do_list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/nv/', None), kwargs={})
1518772140.477 DEBUG gcsfs.core _call(get, b/{}/o/, args=('pangeo-data',), kwargs={'delimiter': '/', 'prefix': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/nv/', 'maxResults': None})
1518772140.509 DEBUG gcsfs.core _list_objects result: {'prefixes': 0, 'items': 3}
1518772140.511 DEBUG gcsfs.core walk(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/sla/', True), kwargs={})
1518772140.512 DEBUG gcsfs.core ls(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/sla/', True), kwargs={})
1518772140.513 DEBUG gcsfs.core _list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/sla/',), kwargs={})
1518772140.513 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/sla/',), kwargs={})
1518772140.514 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/sla/
1518772140.515 DEBUG gcsfs.core _do_list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/sla/', None), kwargs={})
1518772140.516 DEBUG gcsfs.core _call(get, b/{}/o/, args=('pangeo-data',), kwargs={'delimiter': '/', 'prefix': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/sla/', 'maxResults': None})
1518772140.688 DEBUG gcsfs.core _call(get, b/{}/o/, args=('pangeo-data',), kwargs={'delimiter': '/', 'prefix': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/sla/', 'maxResults': None, 'pageToken': 'CkBkYXRhc2V0LWR1YWNzLXJlcC1nbG9iYWwtbWVyZ2VkLWFsbHNhdC1waHktbDQtdjMtYWx0L3NsYS8yOTMuMC4w'})
1518772140.836 DEBUG gcsfs.core _list_objects result: {'prefixes': 0, 'items': 1783}
1518772140.844 DEBUG gcsfs.core walk(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/time/', True), kwargs={})
1518772140.846 DEBUG gcsfs.core ls(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/time/', True), kwargs={})
1518772140.848 DEBUG gcsfs.core _list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/time/',), kwargs={})
1518772140.849 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/time/',), kwargs={})
1518772140.850 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/time/
1518772140.851 DEBUG gcsfs.core _do_list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/time/', None), kwargs={})
1518772140.852 DEBUG gcsfs.core _call(get, b/{}/o/, args=('pangeo-data',), kwargs={'delimiter': '/', 'prefix': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/time/', 'maxResults': None})
1518772140.890 DEBUG gcsfs.core _list_objects result: {'prefixes': 0, 'items': 3}
1518772140.892 DEBUG gcsfs.core walk(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/ugos/', True), kwargs={})
1518772140.893 DEBUG gcsfs.core ls(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/ugos/', True), kwargs={})
1518772140.894 DEBUG gcsfs.core _list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/ugos/',), kwargs={})
1518772140.895 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/ugos/',), kwargs={})
1518772140.896 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/ugos/
1518772140.897 DEBUG gcsfs.core _do_list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/ugos/', None), kwargs={})
1518772140.898 DEBUG gcsfs.core _call(get, b/{}/o/, args=('pangeo-data',), kwargs={'delimiter': '/', 'prefix': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/ugos/', 'maxResults': None})
1518772141.097 DEBUG gcsfs.core _call(get, b/{}/o/, args=('pangeo-data',), kwargs={'delimiter': '/', 'prefix': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/ugos/', 'maxResults': None, 'pageToken': 'CkFkYXRhc2V0LWR1YWNzLXJlcC1nbG9iYWwtbWVyZ2VkLWFsbHNhdC1waHktbDQtdjMtYWx0L3Vnb3MvMjkzLjAuMA=='})
1518772141.261 DEBUG gcsfs.core _list_objects result: {'prefixes': 0, 'items': 1783}
1518772141.270 DEBUG gcsfs.core walk(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/ugosa/', True), kwargs={})
1518772141.271 DEBUG gcsfs.core ls(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/ugosa/', True), kwargs={})
1518772141.272 DEBUG gcsfs.core _list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/ugosa/',), kwargs={})
1518772141.273 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/ugosa/',), kwargs={})
1518772141.274 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/ugosa/
1518772141.275 DEBUG gcsfs.core _do_list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/ugosa/', None), kwargs={})
1518772141.276 DEBUG gcsfs.core _call(get, b/{}/o/, args=('pangeo-data',), kwargs={'delimiter': '/', 'prefix': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/ugosa/', 'maxResults': None})
1518772141.504 DEBUG gcsfs.core _call(get, b/{}/o/, args=('pangeo-data',), kwargs={'delimiter': '/', 'prefix': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/ugosa/', 'maxResults': None, 'pageToken': 'CkJkYXRhc2V0LWR1YWNzLXJlcC1nbG9iYWwtbWVyZ2VkLWFsbHNhdC1waHktbDQtdjMtYWx0L3Vnb3NhLzI5My4wLjA='})
1518772141.670 DEBUG gcsfs.core _list_objects result: {'prefixes': 0, 'items': 1783}
1518772141.678 DEBUG gcsfs.core walk(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/vgos/', True), kwargs={})
1518772141.680 DEBUG gcsfs.core ls(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/vgos/', True), kwargs={})
1518772141.681 DEBUG gcsfs.core _list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/vgos/',), kwargs={})
1518772141.683 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/vgos/',), kwargs={})
1518772141.684 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/vgos/
1518772141.685 DEBUG gcsfs.core _do_list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/vgos/', None), kwargs={})
1518772141.686 DEBUG gcsfs.core _call(get, b/{}/o/, args=('pangeo-data',), kwargs={'delimiter': '/', 'prefix': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/vgos/', 'maxResults': None})
1518772141.882 DEBUG gcsfs.core _call(get, b/{}/o/, args=('pangeo-data',), kwargs={'delimiter': '/', 'prefix': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/vgos/', 'maxResults': None, 'pageToken': 'CkFkYXRhc2V0LWR1YWNzLXJlcC1nbG9iYWwtbWVyZ2VkLWFsbHNhdC1waHktbDQtdjMtYWx0L3Znb3MvMjkzLjAuMA=='})
1518772142.078 DEBUG gcsfs.core _list_objects result: {'prefixes': 0, 'items': 1783}
1518772142.087 DEBUG gcsfs.core walk(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/vgosa/', True), kwargs={})
1518772142.091 DEBUG gcsfs.core ls(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/vgosa/', True), kwargs={})
1518772142.092 DEBUG gcsfs.core _list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/vgosa/',), kwargs={})
1518772142.092 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/vgosa/',), kwargs={})
1518772142.093 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/vgosa/
1518772142.094 DEBUG gcsfs.core _do_list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/vgosa/', None), kwargs={})
1518772142.096 DEBUG gcsfs.core _call(get, b/{}/o/, args=('pangeo-data',), kwargs={'delimiter': '/', 'prefix': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/vgosa/', 'maxResults': None})
1518772142.291 DEBUG gcsfs.core _call(get, b/{}/o/, args=('pangeo-data',), kwargs={'delimiter': '/', 'prefix': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/vgosa/', 'maxResults': None, 'pageToken': 'CkJkYXRhc2V0LWR1YWNzLXJlcC1nbG9iYWwtbWVyZ2VkLWFsbHNhdC1waHktbDQtdjMtYWx0L3Znb3NhLzI5My4wLjA='})
1518772142.498 DEBUG gcsfs.core _list_objects result: {'prefixes': 0, 'items': 1783}
1518772142.507 DEBUG gcsfs.core ls(args=('pangeo-data', True), kwargs={})
1518772142.512 DEBUG gcsfs.core _list_objects(args=('pangeo-data/',), kwargs={})
1518772142.513 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/',), kwargs={})
1518772142.514 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/
1518772142.516 DEBUG gcsfs.core _do_list_objects(args=('pangeo-data/', None), kwargs={})
1518772142.517 DEBUG gcsfs.core _call(get, b/{}/o/, args=('pangeo-data',), kwargs={'delimiter': '/', 'prefix': None, 'maxResults': None})
1518772142.641 DEBUG gcsfs.core _list_objects result: {'prefixes': 9, 'items': 0}
1518772142.718 DEBUG gcsfs.core exists(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zattrs/.zarray',), kwargs={})
1518772142.721 DEBUG gcsfs.core info(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zattrs/.zarray',), kwargs={})
1518772142.723 DEBUG gcsfs.core _get_object(pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zattrs/.zarray)
1518772142.725 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zattrs/',), kwargs={})
1518772142.726 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zattrs/
1518772142.727 DEBUG gcsfs.core _call(get, b/{}/o/{}, args=('pangeo-data', 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zattrs/.zarray'), kwargs={})
1518772142.762 DEBUG gcsfs.core info FileNotFound at path: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zattrs/.zarray
1518772142.764 DEBUG gcsfs.core ls(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zattrs', True), kwargs={})
1518772142.765 DEBUG gcsfs.core _list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zattrs',), kwargs={})
1518772142.766 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zattrs',), kwargs={})
1518772142.767 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zattrs
1518772142.768 DEBUG gcsfs.core _do_list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zattrs', None), kwargs={})
1518772142.768 DEBUG gcsfs.core _call(get, b/{}/o/, args=('pangeo-data',), kwargs={'delimiter': '/', 'prefix': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zattrs', 'maxResults': None})
1518772142.796 DEBUG gcsfs.core _list_objects result: {'prefixes': 0, 'items': 1}
1518772142.798 DEBUG gcsfs.core _list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zattrs/',), kwargs={})
1518772142.800 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zattrs/',), kwargs={})
1518772142.801 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zattrs/
1518772142.802 DEBUG gcsfs.core _do_list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zattrs/', None), kwargs={})
1518772142.803 DEBUG gcsfs.core _call(get, b/{}/o/, args=('pangeo-data',), kwargs={'delimiter': '/', 'prefix': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zattrs/', 'maxResults': None})
1518772142.839 DEBUG gcsfs.core _list_objects result: {'prefixes': 0, 'items': 0}
1518772142.841 DEBUG gcsfs.core exists(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zgroup/.zarray',), kwargs={})
1518772142.842 DEBUG gcsfs.core info(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zgroup/.zarray',), kwargs={})
1518772142.843 DEBUG gcsfs.core _get_object(pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zgroup/.zarray)
1518772142.844 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zgroup/',), kwargs={})
1518772142.845 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zgroup/
1518772142.846 DEBUG gcsfs.core _call(get, b/{}/o/{}, args=('pangeo-data', 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zgroup/.zarray'), kwargs={})
1518772142.880 DEBUG gcsfs.core info FileNotFound at path: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zgroup/.zarray
1518772142.881 DEBUG gcsfs.core ls(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zgroup', True), kwargs={})
1518772142.882 DEBUG gcsfs.core _list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zgroup',), kwargs={})
1518772142.883 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zgroup',), kwargs={})
1518772142.885 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zgroup
1518772142.886 DEBUG gcsfs.core _do_list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zgroup', None), kwargs={})
1518772142.887 DEBUG gcsfs.core _call(get, b/{}/o/, args=('pangeo-data',), kwargs={'delimiter': '/', 'prefix': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zgroup', 'maxResults': None})
1518772142.924 DEBUG gcsfs.core _list_objects result: {'prefixes': 0, 'items': 1}
1518772142.925 DEBUG gcsfs.core _list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zgroup/',), kwargs={})
1518772142.927 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zgroup/',), kwargs={})
1518772142.928 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zgroup/
1518772142.929 DEBUG gcsfs.core _do_list_objects(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zgroup/', None), kwargs={})
1518772142.930 DEBUG gcsfs.core _call(get, b/{}/o/, args=('pangeo-data',), kwargs={'delimiter': '/', 'prefix': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/.zgroup/', 'maxResults': None})
1518772142.964 DEBUG gcsfs.core _list_objects result: {'prefixes': 0, 'items': 0}
1518772142.968 DEBUG gcsfs.core exists(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/.zarray',), kwargs={})
1518772142.970 DEBUG gcsfs.core info(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/.zarray',), kwargs={})
1518772142.971 DEBUG gcsfs.core _get_object(pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/.zarray)
1518772142.972 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/',), kwargs={})
1518772142.973 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/
1518772142.975 DEBUG gcsfs.core found cached object: [{'kind': 'storage#object', 'id': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/.zarray/1517251554296743', 'selfLink': 'https://www.googleapis.com/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Fadt%2F.zarray', 'name': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/.zarray', 'bucket': 'pangeo-data', 'generation': '1517251554296743', 'metageneration': '1', 'timeCreated': '2018-01-29T18:45:54.273Z', 'updated': '2018-01-29T18:45:54.273Z', 'storageClass': 'REGIONAL', 'timeStorageClassUpdated': '2018-01-29T18:45:54.273Z', 'size': 371, 'md5Hash': 'ijnyP1l9SpsV3qtG1T9Uig==', 'mediaLink': 'https://www.googleapis.com/download/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Fadt%2F.zarray?generation=1517251554296743&alt=media', 'crc32c': 'HDOHbA==', 'etag': 'CKeHt7/q/dgCEAE=', 'path': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/.zarray'}]
1518772142.976 DEBUG gcsfs.core open(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/.zarray', 'rb', None, None, None, None), kwargs={})
1518772142.977 DEBUG gcsfs.core __init__(args=(<gcsfs.core.GCSFileSystem object at 0x7f8d67f895c0>, 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/.zarray', 'rb', 5242880, None, 'none', None), kwargs={})
1518772142.978 DEBUG gcsfs.core info(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/.zarray',), kwargs={})
1518772142.979 DEBUG gcsfs.core _get_object(pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/.zarray)
1518772142.980 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/',), kwargs={})
1518772142.981 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/
1518772142.982 DEBUG gcsfs.core found cached object: [{'kind': 'storage#object', 'id': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/.zarray/1517251554296743', 'selfLink': 'https://www.googleapis.com/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Fadt%2F.zarray', 'name': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/.zarray', 'bucket': 'pangeo-data', 'generation': '1517251554296743', 'metageneration': '1', 'timeCreated': '2018-01-29T18:45:54.273Z', 'updated': '2018-01-29T18:45:54.273Z', 'storageClass': 'REGIONAL', 'timeStorageClassUpdated': '2018-01-29T18:45:54.273Z', 'size': 371, 'md5Hash': 'ijnyP1l9SpsV3qtG1T9Uig==', 'mediaLink': 'https://www.googleapis.com/download/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Fadt%2F.zarray?generation=1517251554296743&alt=media', 'crc32c': 'HDOHbA==', 'etag': 'CKeHt7/q/dgCEAE=', 'path': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/.zarray'}]
1518772142.983 DEBUG gcsfs.core __enter__(args=(), kwargs={})
1518772142.984 DEBUG gcsfs.core _fetch(args=(0, 371), kwargs={})
--- Logging error ---
Traceback (most recent call last):
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 992, in emit
    msg = self.format(record)
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 838, in format
    return fmt.format(record)
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 575, in format
    record.message = record.getMessage()
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 338, in getMessage
    msg = msg % self.args
TypeError: not all arguments converted during string formatting
Call stack:
  File "/opt/conda/lib/python3.6/runpy.py", line 193, in _run_module_as_main
    "__main__", mod_spec)
  File "/opt/conda/lib/python3.6/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/__main__.py", line 3, in <module>
    app.launch_new_instance()
  File "/opt/conda/lib/python3.6/site-packages/traitlets/config/application.py", line 658, in launch_instance
    app.start()
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelapp.py", line 477, in start
    ioloop.IOLoop.instance().start()
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/ioloop.py", line 177, in start
    super(ZMQIOLoop, self).start()
  File "/opt/conda/lib/python3.6/site-packages/tornado/ioloop.py", line 888, in start
    handler_func(fd_obj, events)
  File "/opt/conda/lib/python3.6/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    return fn(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 440, in _handle_events
    self._handle_recv()
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 472, in _handle_recv
    self._run_callback(callback, msg)
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 414, in _run_callback
    callback(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    return fn(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 283, in dispatcher
    return self.dispatch_shell(stream, msg)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 235, in dispatch_shell
    handler(stream, idents, msg)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 399, in execute_request
    user_expressions, allow_stdin)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/ipkernel.py", line 196, in do_execute
    res = shell.run_cell(code, store_history=store_history, silent=silent)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/zmqshell.py", line 533, in run_cell
    return super(ZMQInteractiveShell, self).run_cell(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2728, in run_cell
    interactivity=interactivity, compiler=compiler, result=result)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2850, in run_ast_nodes
    if self.run_code(code, result):
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2910, in run_code
    exec(code_obj, self.user_global_ns, self.user_ns)
  File "<ipython-input-9-051a91e550af>", line 5, in <module>
    get_ipython().run_line_magic('time', 'ds = xr.open_zarr(gcsmap)')
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2095, in run_line_magic
    result = fn(*args,**kwargs)
  File "<decorator-gen-62>", line 2, in time
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/magic.py", line 187, in <lambda>
    call = lambda f, *a, **k: f(*a, **k)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/magics/execution.py", line 1238, in time
    exec(code, glob, local_ns)
  File "<timed exec>", line 1, in <module>
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 473, in open_zarr
    ds = maybe_decode_store(zarr_store)
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 461, in maybe_decode_store
    drop_variables=drop_variables)
  File "/opt/conda/lib/python3.6/site-packages/xarray/conventions.py", line 598, in decode_cf
    vars, attrs = obj.load()
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/common.py", line 133, in load
    for k, v in self.get_variables().items())
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 314, in get_variables
    for k, v in self.ds.arrays())
  File "/opt/conda/lib/python3.6/site-packages/xarray/core/utils.py", line 309, in FrozenOrderedDict
    return Frozen(OrderedDict(*args, **kwargs))
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 313, in <genexpr>
    return FrozenOrderedDict((k, self.open_store_variable(k, v))
  File "/opt/conda/lib/python3.6/site-packages/zarr/hierarchy.py", line 458, in arrays
    synchronizer=self._synchronizer)
  File "/opt/conda/lib/python3.6/site-packages/zarr/core.py", line 123, in __init__
    self._load_metadata()
  File "/opt/conda/lib/python3.6/site-packages/zarr/core.py", line 140, in _load_metadata
    self._load_metadata_nosync()
  File "/opt/conda/lib/python3.6/site-packages/zarr/core.py", line 149, in _load_metadata_nosync
    meta_bytes = self._store[mkey]
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/mapping.py", line 68, in __getitem__
    result = f.read()
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1280, in read
    self._fetch(self.loc, self.loc + length)
  File "<decorator-gen-156>", line 2, in _fetch
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 48, in _tracemethod
    return f(self, *args, **kwargs)
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1239, in _fetch
    self.end)
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1344, in _fetch_range
    logger.debug("Fetch: {}, {}-{}", obj_dict['name'], start, end)
Message: 'Fetch: {}, {}-{}'
Arguments: ('dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/.zarray', 0, 10485760)
1518772143.091 DEBUG gcsfs.core __exit__(args=(None, None, None), kwargs={})
1518772143.092 DEBUG gcsfs.core close(args=(), kwargs={})
1518772143.093 DEBUG gcsfs.core __del__(args=(), kwargs={})
1518772143.094 DEBUG gcsfs.core close(args=(), kwargs={})
1518772143.096 DEBUG gcsfs.core exists(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/.zarray',), kwargs={})
1518772143.097 DEBUG gcsfs.core info(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/.zarray',), kwargs={})
1518772143.098 DEBUG gcsfs.core _get_object(pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/.zarray)
1518772143.098 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/',), kwargs={})
1518772143.099 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/
1518772143.101 DEBUG gcsfs.core found cached object: [{'kind': 'storage#object', 'id': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/.zarray/1517251554296743', 'selfLink': 'https://www.googleapis.com/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Fadt%2F.zarray', 'name': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/.zarray', 'bucket': 'pangeo-data', 'generation': '1517251554296743', 'metageneration': '1', 'timeCreated': '2018-01-29T18:45:54.273Z', 'updated': '2018-01-29T18:45:54.273Z', 'storageClass': 'REGIONAL', 'timeStorageClassUpdated': '2018-01-29T18:45:54.273Z', 'size': 371, 'md5Hash': 'ijnyP1l9SpsV3qtG1T9Uig==', 'mediaLink': 'https://www.googleapis.com/download/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Fadt%2F.zarray?generation=1517251554296743&alt=media', 'crc32c': 'HDOHbA==', 'etag': 'CKeHt7/q/dgCEAE=', 'path': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/.zarray'}]
1518772143.102 DEBUG gcsfs.core open(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/.zarray', 'rb', None, None, None, None), kwargs={})
1518772143.102 DEBUG gcsfs.core __init__(args=(<gcsfs.core.GCSFileSystem object at 0x7f8d67f895c0>, 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/.zarray', 'rb', 5242880, None, 'none', None), kwargs={})
1518772143.103 DEBUG gcsfs.core info(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/.zarray',), kwargs={})
1518772143.104 DEBUG gcsfs.core _get_object(pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/.zarray)
1518772143.105 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/',), kwargs={})
1518772143.106 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/
1518772143.107 DEBUG gcsfs.core found cached object: [{'kind': 'storage#object', 'id': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/.zarray/1517251554296743', 'selfLink': 'https://www.googleapis.com/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Fadt%2F.zarray', 'name': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/.zarray', 'bucket': 'pangeo-data', 'generation': '1517251554296743', 'metageneration': '1', 'timeCreated': '2018-01-29T18:45:54.273Z', 'updated': '2018-01-29T18:45:54.273Z', 'storageClass': 'REGIONAL', 'timeStorageClassUpdated': '2018-01-29T18:45:54.273Z', 'size': 371, 'md5Hash': 'ijnyP1l9SpsV3qtG1T9Uig==', 'mediaLink': 'https://www.googleapis.com/download/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Fadt%2F.zarray?generation=1517251554296743&alt=media', 'crc32c': 'HDOHbA==', 'etag': 'CKeHt7/q/dgCEAE=', 'path': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/.zarray'}]
1518772143.108 DEBUG gcsfs.core __enter__(args=(), kwargs={})
1518772143.109 DEBUG gcsfs.core _fetch(args=(0, 371), kwargs={})
--- Logging error ---
Traceback (most recent call last):
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 992, in emit
    msg = self.format(record)
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 838, in format
    return fmt.format(record)
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 575, in format
    record.message = record.getMessage()
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 338, in getMessage
    msg = msg % self.args
TypeError: not all arguments converted during string formatting
Call stack:
  File "/opt/conda/lib/python3.6/runpy.py", line 193, in _run_module_as_main
    "__main__", mod_spec)
  File "/opt/conda/lib/python3.6/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/__main__.py", line 3, in <module>
    app.launch_new_instance()
  File "/opt/conda/lib/python3.6/site-packages/traitlets/config/application.py", line 658, in launch_instance
    app.start()
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelapp.py", line 477, in start
    ioloop.IOLoop.instance().start()
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/ioloop.py", line 177, in start
    super(ZMQIOLoop, self).start()
  File "/opt/conda/lib/python3.6/site-packages/tornado/ioloop.py", line 888, in start
    handler_func(fd_obj, events)
  File "/opt/conda/lib/python3.6/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    return fn(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 440, in _handle_events
    self._handle_recv()
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 472, in _handle_recv
    self._run_callback(callback, msg)
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 414, in _run_callback
    callback(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    return fn(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 283, in dispatcher
    return self.dispatch_shell(stream, msg)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 235, in dispatch_shell
    handler(stream, idents, msg)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 399, in execute_request
    user_expressions, allow_stdin)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/ipkernel.py", line 196, in do_execute
    res = shell.run_cell(code, store_history=store_history, silent=silent)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/zmqshell.py", line 533, in run_cell
    return super(ZMQInteractiveShell, self).run_cell(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2728, in run_cell
    interactivity=interactivity, compiler=compiler, result=result)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2850, in run_ast_nodes
    if self.run_code(code, result):
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2910, in run_code
    exec(code_obj, self.user_global_ns, self.user_ns)
  File "<ipython-input-9-051a91e550af>", line 5, in <module>
    get_ipython().run_line_magic('time', 'ds = xr.open_zarr(gcsmap)')
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2095, in run_line_magic
    result = fn(*args,**kwargs)
  File "<decorator-gen-62>", line 2, in time
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/magic.py", line 187, in <lambda>
    call = lambda f, *a, **k: f(*a, **k)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/magics/execution.py", line 1238, in time
    exec(code, glob, local_ns)
  File "<timed exec>", line 1, in <module>
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 473, in open_zarr
    ds = maybe_decode_store(zarr_store)
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 461, in maybe_decode_store
    drop_variables=drop_variables)
  File "/opt/conda/lib/python3.6/site-packages/xarray/conventions.py", line 598, in decode_cf
    vars, attrs = obj.load()
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/common.py", line 133, in load
    for k, v in self.get_variables().items())
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 314, in get_variables
    for k, v in self.ds.arrays())
  File "/opt/conda/lib/python3.6/site-packages/xarray/core/utils.py", line 309, in FrozenOrderedDict
    return Frozen(OrderedDict(*args, **kwargs))
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 314, in <genexpr>
    for k, v in self.ds.arrays())
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 298, in open_store_variable
    data = indexing.LazilyIndexedArray(ZarrArrayWrapper(name, self))
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 76, in __init__
    array = self.get_array()
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 83, in get_array
    return self.datastore.ds[self.variable_name]
  File "/opt/conda/lib/python3.6/site-packages/zarr/hierarchy.py", line 328, in __getitem__
    synchronizer=self._synchronizer, cache_attrs=self.attrs.cache)
  File "/opt/conda/lib/python3.6/site-packages/zarr/core.py", line 123, in __init__
    self._load_metadata()
  File "/opt/conda/lib/python3.6/site-packages/zarr/core.py", line 140, in _load_metadata
    self._load_metadata_nosync()
  File "/opt/conda/lib/python3.6/site-packages/zarr/core.py", line 149, in _load_metadata_nosync
    meta_bytes = self._store[mkey]
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/mapping.py", line 68, in __getitem__
    result = f.read()
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1280, in read
    self._fetch(self.loc, self.loc + length)
  File "<decorator-gen-156>", line 2, in _fetch
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 48, in _tracemethod
    return f(self, *args, **kwargs)
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1239, in _fetch
    self.end)
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1344, in _fetch_range
    logger.debug("Fetch: {}, {}-{}", obj_dict['name'], start, end)
Message: 'Fetch: {}, {}-{}'
Arguments: ('dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/.zarray', 0, 10485760)
1518772143.153 DEBUG gcsfs.core __exit__(args=(None, None, None), kwargs={})
1518772143.156 DEBUG gcsfs.core close(args=(), kwargs={})
1518772143.157 DEBUG gcsfs.core __del__(args=(), kwargs={})
1518772143.158 DEBUG gcsfs.core close(args=(), kwargs={})
1518772143.159 DEBUG gcsfs.core open(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/.zattrs', 'rb', None, None, None, None), kwargs={})
1518772143.160 DEBUG gcsfs.core __init__(args=(<gcsfs.core.GCSFileSystem object at 0x7f8d67f895c0>, 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/.zattrs', 'rb', 5242880, None, 'none', None), kwargs={})
1518772143.161 DEBUG gcsfs.core info(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/.zattrs',), kwargs={})
1518772143.162 DEBUG gcsfs.core _get_object(pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/.zattrs)
1518772143.163 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/',), kwargs={})
1518772143.163 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/
1518772143.165 DEBUG gcsfs.core found cached object: [{'kind': 'storage#object', 'id': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/.zattrs/1517251554861240', 'selfLink': 'https://www.googleapis.com/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Fadt%2F.zattrs', 'name': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/.zattrs', 'bucket': 'pangeo-data', 'generation': '1517251554861240', 'metageneration': '1', 'timeCreated': '2018-01-29T18:45:54.845Z', 'updated': '2018-01-29T18:45:54.845Z', 'storageClass': 'REGIONAL', 'timeStorageClassUpdated': '2018-01-29T18:45:54.845Z', 'size': 481, 'md5Hash': 'VSWJeby3ZGXAJZ9yWgDCww==', 'mediaLink': 'https://www.googleapis.com/download/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Fadt%2F.zattrs?generation=1517251554861240&alt=media', 'crc32c': 'T89qpA==', 'etag': 'CLjB2b/q/dgCEAE=', 'path': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/.zattrs'}]
1518772143.166 DEBUG gcsfs.core __enter__(args=(), kwargs={})
1518772143.167 DEBUG gcsfs.core _fetch(args=(0, 481), kwargs={})
--- Logging error ---
Traceback (most recent call last):
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 992, in emit
    msg = self.format(record)
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 838, in format
    return fmt.format(record)
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 575, in format
    record.message = record.getMessage()
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 338, in getMessage
    msg = msg % self.args
TypeError: not all arguments converted during string formatting
Call stack:
  File "/opt/conda/lib/python3.6/runpy.py", line 193, in _run_module_as_main
    "__main__", mod_spec)
  File "/opt/conda/lib/python3.6/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/__main__.py", line 3, in <module>
    app.launch_new_instance()
  File "/opt/conda/lib/python3.6/site-packages/traitlets/config/application.py", line 658, in launch_instance
    app.start()
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelapp.py", line 477, in start
    ioloop.IOLoop.instance().start()
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/ioloop.py", line 177, in start
    super(ZMQIOLoop, self).start()
  File "/opt/conda/lib/python3.6/site-packages/tornado/ioloop.py", line 888, in start
    handler_func(fd_obj, events)
  File "/opt/conda/lib/python3.6/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    return fn(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 440, in _handle_events
    self._handle_recv()
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 472, in _handle_recv
    self._run_callback(callback, msg)
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 414, in _run_callback
    callback(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    return fn(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 283, in dispatcher
    return self.dispatch_shell(stream, msg)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 235, in dispatch_shell
    handler(stream, idents, msg)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 399, in execute_request
    user_expressions, allow_stdin)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/ipkernel.py", line 196, in do_execute
    res = shell.run_cell(code, store_history=store_history, silent=silent)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/zmqshell.py", line 533, in run_cell
    return super(ZMQInteractiveShell, self).run_cell(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2728, in run_cell
    interactivity=interactivity, compiler=compiler, result=result)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2850, in run_ast_nodes
    if self.run_code(code, result):
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2910, in run_code
    exec(code_obj, self.user_global_ns, self.user_ns)
  File "<ipython-input-9-051a91e550af>", line 5, in <module>
    get_ipython().run_line_magic('time', 'ds = xr.open_zarr(gcsmap)')
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2095, in run_line_magic
    result = fn(*args,**kwargs)
  File "<decorator-gen-62>", line 2, in time
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/magic.py", line 187, in <lambda>
    call = lambda f, *a, **k: f(*a, **k)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/magics/execution.py", line 1238, in time
    exec(code, glob, local_ns)
  File "<timed exec>", line 1, in <module>
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 473, in open_zarr
    ds = maybe_decode_store(zarr_store)
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 461, in maybe_decode_store
    drop_variables=drop_variables)
  File "/opt/conda/lib/python3.6/site-packages/xarray/conventions.py", line 598, in decode_cf
    vars, attrs = obj.load()
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/common.py", line 133, in load
    for k, v in self.get_variables().items())
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 314, in get_variables
    for k, v in self.ds.arrays())
  File "/opt/conda/lib/python3.6/site-packages/xarray/core/utils.py", line 309, in FrozenOrderedDict
    return Frozen(OrderedDict(*args, **kwargs))
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 314, in <genexpr>
    for k, v in self.ds.arrays())
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 300, in open_store_variable
    _DIMENSION_KEY)
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 196, in _get_zarr_dims_and_attrs
    dimensions = zarr_obj.attrs[dimension_key]
  File "/opt/conda/lib/python3.6/site-packages/zarr/attrs.py", line 67, in __getitem__
    return self.asdict()[item]
  File "/opt/conda/lib/python3.6/site-packages/zarr/attrs.py", line 53, in asdict
    d = self._get_nosync()
  File "/opt/conda/lib/python3.6/site-packages/zarr/attrs.py", line 42, in _get_nosync
    data = self.store[self.key]
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/mapping.py", line 68, in __getitem__
    result = f.read()
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1280, in read
    self._fetch(self.loc, self.loc + length)
  File "<decorator-gen-156>", line 2, in _fetch
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 48, in _tracemethod
    return f(self, *args, **kwargs)
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1239, in _fetch
    self.end)
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1344, in _fetch_range
    logger.debug("Fetch: {}, {}-{}", obj_dict['name'], start, end)
Message: 'Fetch: {}, {}-{}'
Arguments: ('dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/adt/.zattrs', 0, 10485760)
1518772143.240 DEBUG gcsfs.core __exit__(args=(None, None, None), kwargs={})
1518772143.242 DEBUG gcsfs.core close(args=(), kwargs={})
1518772143.244 DEBUG gcsfs.core __del__(args=(), kwargs={})
1518772143.245 DEBUG gcsfs.core close(args=(), kwargs={})
1518772143.246 DEBUG gcsfs.core exists(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray',), kwargs={})
1518772143.247 DEBUG gcsfs.core info(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray',), kwargs={})
1518772143.248 DEBUG gcsfs.core _get_object(pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray)
1518772143.249 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/',), kwargs={})
1518772143.250 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/
1518772143.251 DEBUG gcsfs.core found cached object: [{'kind': 'storage#object', 'id': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray/1517251342171118', 'selfLink': 'https://www.googleapis.com/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Fcrs%2F.zarray', 'name': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray', 'bucket': 'pangeo-data', 'generation': '1517251342171118', 'metageneration': '1', 'timeCreated': '2018-01-29T18:42:22.133Z', 'updated': '2018-01-29T18:42:22.133Z', 'storageClass': 'REGIONAL', 'timeStorageClassUpdated': '2018-01-29T18:42:22.133Z', 'size': 166, 'md5Hash': '9CsCC+aV78cxg9+tOOvROw==', 'mediaLink': 'https://www.googleapis.com/download/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Fcrs%2F.zarray?generation=1517251342171118&alt=media', 'crc32c': 'oDZIWA==', 'etag': 'CO73o9rp/dgCEAE=', 'path': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray'}]
1518772143.252 DEBUG gcsfs.core open(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray', 'rb', None, None, None, None), kwargs={})
1518772143.252 DEBUG gcsfs.core __init__(args=(<gcsfs.core.GCSFileSystem object at 0x7f8d67f895c0>, 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray', 'rb', 5242880, None, 'none', None), kwargs={})
1518772143.253 DEBUG gcsfs.core info(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray',), kwargs={})
1518772143.254 DEBUG gcsfs.core _get_object(pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray)
1518772143.255 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/',), kwargs={})
1518772143.256 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/
1518772143.257 DEBUG gcsfs.core found cached object: [{'kind': 'storage#object', 'id': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray/1517251342171118', 'selfLink': 'https://www.googleapis.com/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Fcrs%2F.zarray', 'name': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray', 'bucket': 'pangeo-data', 'generation': '1517251342171118', 'metageneration': '1', 'timeCreated': '2018-01-29T18:42:22.133Z', 'updated': '2018-01-29T18:42:22.133Z', 'storageClass': 'REGIONAL', 'timeStorageClassUpdated': '2018-01-29T18:42:22.133Z', 'size': 166, 'md5Hash': '9CsCC+aV78cxg9+tOOvROw==', 'mediaLink': 'https://www.googleapis.com/download/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Fcrs%2F.zarray?generation=1517251342171118&alt=media', 'crc32c': 'oDZIWA==', 'etag': 'CO73o9rp/dgCEAE=', 'path': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray'}]
1518772143.258 DEBUG gcsfs.core __enter__(args=(), kwargs={})
1518772143.259 DEBUG gcsfs.core _fetch(args=(0, 166), kwargs={})
--- Logging error ---
Traceback (most recent call last):
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 992, in emit
    msg = self.format(record)
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 838, in format
    return fmt.format(record)
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 575, in format
    record.message = record.getMessage()
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 338, in getMessage
    msg = msg % self.args
TypeError: not all arguments converted during string formatting
Call stack:
  File "/opt/conda/lib/python3.6/runpy.py", line 193, in _run_module_as_main
    "__main__", mod_spec)
  File "/opt/conda/lib/python3.6/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/__main__.py", line 3, in <module>
    app.launch_new_instance()
  File "/opt/conda/lib/python3.6/site-packages/traitlets/config/application.py", line 658, in launch_instance
    app.start()
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelapp.py", line 477, in start
    ioloop.IOLoop.instance().start()
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/ioloop.py", line 177, in start
    super(ZMQIOLoop, self).start()
  File "/opt/conda/lib/python3.6/site-packages/tornado/ioloop.py", line 888, in start
    handler_func(fd_obj, events)
  File "/opt/conda/lib/python3.6/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    return fn(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 440, in _handle_events
    self._handle_recv()
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 472, in _handle_recv
    self._run_callback(callback, msg)
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 414, in _run_callback
    callback(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    return fn(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 283, in dispatcher
    return self.dispatch_shell(stream, msg)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 235, in dispatch_shell
    handler(stream, idents, msg)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 399, in execute_request
    user_expressions, allow_stdin)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/ipkernel.py", line 196, in do_execute
    res = shell.run_cell(code, store_history=store_history, silent=silent)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/zmqshell.py", line 533, in run_cell
    return super(ZMQInteractiveShell, self).run_cell(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2728, in run_cell
    interactivity=interactivity, compiler=compiler, result=result)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2850, in run_ast_nodes
    if self.run_code(code, result):
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2910, in run_code
    exec(code_obj, self.user_global_ns, self.user_ns)
  File "<ipython-input-9-051a91e550af>", line 5, in <module>
    get_ipython().run_line_magic('time', 'ds = xr.open_zarr(gcsmap)')
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2095, in run_line_magic
    result = fn(*args,**kwargs)
  File "<decorator-gen-62>", line 2, in time
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/magic.py", line 187, in <lambda>
    call = lambda f, *a, **k: f(*a, **k)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/magics/execution.py", line 1238, in time
    exec(code, glob, local_ns)
  File "<timed exec>", line 1, in <module>
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 473, in open_zarr
    ds = maybe_decode_store(zarr_store)
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 461, in maybe_decode_store
    drop_variables=drop_variables)
  File "/opt/conda/lib/python3.6/site-packages/xarray/conventions.py", line 598, in decode_cf
    vars, attrs = obj.load()
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/common.py", line 133, in load
    for k, v in self.get_variables().items())
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 314, in get_variables
    for k, v in self.ds.arrays())
  File "/opt/conda/lib/python3.6/site-packages/xarray/core/utils.py", line 309, in FrozenOrderedDict
    return Frozen(OrderedDict(*args, **kwargs))
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 313, in <genexpr>
    return FrozenOrderedDict((k, self.open_store_variable(k, v))
  File "/opt/conda/lib/python3.6/site-packages/zarr/hierarchy.py", line 458, in arrays
    synchronizer=self._synchronizer)
  File "/opt/conda/lib/python3.6/site-packages/zarr/core.py", line 123, in __init__
    self._load_metadata()
  File "/opt/conda/lib/python3.6/site-packages/zarr/core.py", line 140, in _load_metadata
    self._load_metadata_nosync()
  File "/opt/conda/lib/python3.6/site-packages/zarr/core.py", line 149, in _load_metadata_nosync
    meta_bytes = self._store[mkey]
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/mapping.py", line 68, in __getitem__
    result = f.read()
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1280, in read
    self._fetch(self.loc, self.loc + length)
  File "<decorator-gen-156>", line 2, in _fetch
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 48, in _tracemethod
    return f(self, *args, **kwargs)
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1239, in _fetch
    self.end)
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1344, in _fetch_range
    logger.debug("Fetch: {}, {}-{}", obj_dict['name'], start, end)
Message: 'Fetch: {}, {}-{}'
Arguments: ('dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray', 0, 10485760)
1518772143.378 DEBUG gcsfs.core __exit__(args=(None, None, None), kwargs={})
1518772143.379 DEBUG gcsfs.core close(args=(), kwargs={})
1518772143.380 DEBUG gcsfs.core __del__(args=(), kwargs={})
1518772143.381 DEBUG gcsfs.core close(args=(), kwargs={})
1518772143.382 DEBUG gcsfs.core exists(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray',), kwargs={})
1518772143.383 DEBUG gcsfs.core info(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray',), kwargs={})
1518772143.384 DEBUG gcsfs.core _get_object(pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray)
1518772143.385 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/',), kwargs={})
1518772143.386 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/
1518772143.387 DEBUG gcsfs.core found cached object: [{'kind': 'storage#object', 'id': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray/1517251342171118', 'selfLink': 'https://www.googleapis.com/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Fcrs%2F.zarray', 'name': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray', 'bucket': 'pangeo-data', 'generation': '1517251342171118', 'metageneration': '1', 'timeCreated': '2018-01-29T18:42:22.133Z', 'updated': '2018-01-29T18:42:22.133Z', 'storageClass': 'REGIONAL', 'timeStorageClassUpdated': '2018-01-29T18:42:22.133Z', 'size': 166, 'md5Hash': '9CsCC+aV78cxg9+tOOvROw==', 'mediaLink': 'https://www.googleapis.com/download/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Fcrs%2F.zarray?generation=1517251342171118&alt=media', 'crc32c': 'oDZIWA==', 'etag': 'CO73o9rp/dgCEAE=', 'path': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray'}]
1518772143.388 DEBUG gcsfs.core open(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray', 'rb', None, None, None, None), kwargs={})
1518772143.389 DEBUG gcsfs.core __init__(args=(<gcsfs.core.GCSFileSystem object at 0x7f8d67f895c0>, 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray', 'rb', 5242880, None, 'none', None), kwargs={})
1518772143.389 DEBUG gcsfs.core info(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray',), kwargs={})
1518772143.390 DEBUG gcsfs.core _get_object(pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray)
1518772143.391 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/',), kwargs={})
1518772143.392 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/
1518772143.393 DEBUG gcsfs.core found cached object: [{'kind': 'storage#object', 'id': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray/1517251342171118', 'selfLink': 'https://www.googleapis.com/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Fcrs%2F.zarray', 'name': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray', 'bucket': 'pangeo-data', 'generation': '1517251342171118', 'metageneration': '1', 'timeCreated': '2018-01-29T18:42:22.133Z', 'updated': '2018-01-29T18:42:22.133Z', 'storageClass': 'REGIONAL', 'timeStorageClassUpdated': '2018-01-29T18:42:22.133Z', 'size': 166, 'md5Hash': '9CsCC+aV78cxg9+tOOvROw==', 'mediaLink': 'https://www.googleapis.com/download/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Fcrs%2F.zarray?generation=1517251342171118&alt=media', 'crc32c': 'oDZIWA==', 'etag': 'CO73o9rp/dgCEAE=', 'path': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray'}]
1518772143.394 DEBUG gcsfs.core __enter__(args=(), kwargs={})
1518772143.395 DEBUG gcsfs.core _fetch(args=(0, 166), kwargs={})
--- Logging error ---
Traceback (most recent call last):
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 992, in emit
    msg = self.format(record)
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 838, in format
    return fmt.format(record)
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 575, in format
    record.message = record.getMessage()
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 338, in getMessage
    msg = msg % self.args
TypeError: not all arguments converted during string formatting
Call stack:
  File "/opt/conda/lib/python3.6/runpy.py", line 193, in _run_module_as_main
    "__main__", mod_spec)
  File "/opt/conda/lib/python3.6/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/__main__.py", line 3, in <module>
    app.launch_new_instance()
  File "/opt/conda/lib/python3.6/site-packages/traitlets/config/application.py", line 658, in launch_instance
    app.start()
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelapp.py", line 477, in start
    ioloop.IOLoop.instance().start()
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/ioloop.py", line 177, in start
    super(ZMQIOLoop, self).start()
  File "/opt/conda/lib/python3.6/site-packages/tornado/ioloop.py", line 888, in start
    handler_func(fd_obj, events)
  File "/opt/conda/lib/python3.6/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    return fn(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 440, in _handle_events
    self._handle_recv()
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 472, in _handle_recv
    self._run_callback(callback, msg)
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 414, in _run_callback
    callback(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    return fn(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 283, in dispatcher
    return self.dispatch_shell(stream, msg)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 235, in dispatch_shell
    handler(stream, idents, msg)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 399, in execute_request
    user_expressions, allow_stdin)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/ipkernel.py", line 196, in do_execute
    res = shell.run_cell(code, store_history=store_history, silent=silent)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/zmqshell.py", line 533, in run_cell
    return super(ZMQInteractiveShell, self).run_cell(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2728, in run_cell
    interactivity=interactivity, compiler=compiler, result=result)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2850, in run_ast_nodes
    if self.run_code(code, result):
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2910, in run_code
    exec(code_obj, self.user_global_ns, self.user_ns)
  File "<ipython-input-9-051a91e550af>", line 5, in <module>
    get_ipython().run_line_magic('time', 'ds = xr.open_zarr(gcsmap)')
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2095, in run_line_magic
    result = fn(*args,**kwargs)
  File "<decorator-gen-62>", line 2, in time
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/magic.py", line 187, in <lambda>
    call = lambda f, *a, **k: f(*a, **k)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/magics/execution.py", line 1238, in time
    exec(code, glob, local_ns)
  File "<timed exec>", line 1, in <module>
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 473, in open_zarr
    ds = maybe_decode_store(zarr_store)
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 461, in maybe_decode_store
    drop_variables=drop_variables)
  File "/opt/conda/lib/python3.6/site-packages/xarray/conventions.py", line 598, in decode_cf
    vars, attrs = obj.load()
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/common.py", line 133, in load
    for k, v in self.get_variables().items())
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 314, in get_variables
    for k, v in self.ds.arrays())
  File "/opt/conda/lib/python3.6/site-packages/xarray/core/utils.py", line 309, in FrozenOrderedDict
    return Frozen(OrderedDict(*args, **kwargs))
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 314, in <genexpr>
    for k, v in self.ds.arrays())
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 298, in open_store_variable
    data = indexing.LazilyIndexedArray(ZarrArrayWrapper(name, self))
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 76, in __init__
    array = self.get_array()
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 83, in get_array
    return self.datastore.ds[self.variable_name]
  File "/opt/conda/lib/python3.6/site-packages/zarr/hierarchy.py", line 328, in __getitem__
    synchronizer=self._synchronizer, cache_attrs=self.attrs.cache)
  File "/opt/conda/lib/python3.6/site-packages/zarr/core.py", line 123, in __init__
    self._load_metadata()
  File "/opt/conda/lib/python3.6/site-packages/zarr/core.py", line 140, in _load_metadata
    self._load_metadata_nosync()
  File "/opt/conda/lib/python3.6/site-packages/zarr/core.py", line 149, in _load_metadata_nosync
    meta_bytes = self._store[mkey]
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/mapping.py", line 68, in __getitem__
    result = f.read()
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1280, in read
    self._fetch(self.loc, self.loc + length)
  File "<decorator-gen-156>", line 2, in _fetch
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 48, in _tracemethod
    return f(self, *args, **kwargs)
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1239, in _fetch
    self.end)
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1344, in _fetch_range
    logger.debug("Fetch: {}, {}-{}", obj_dict['name'], start, end)
Message: 'Fetch: {}, {}-{}'
Arguments: ('dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray', 0, 10485760)
1518772143.486 DEBUG gcsfs.core __exit__(args=(None, None, None), kwargs={})
1518772143.488 DEBUG gcsfs.core close(args=(), kwargs={})
1518772143.489 DEBUG gcsfs.core __del__(args=(), kwargs={})
1518772143.490 DEBUG gcsfs.core close(args=(), kwargs={})
1518772143.491 DEBUG gcsfs.core open(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zattrs', 'rb', None, None, None, None), kwargs={})
1518772143.491 DEBUG gcsfs.core __init__(args=(<gcsfs.core.GCSFileSystem object at 0x7f8d67f895c0>, 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zattrs', 'rb', 5242880, None, 'none', None), kwargs={})
1518772143.492 DEBUG gcsfs.core info(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zattrs',), kwargs={})
1518772143.493 DEBUG gcsfs.core _get_object(pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zattrs)
1518772143.494 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/',), kwargs={})
1518772143.496 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/
1518772143.497 DEBUG gcsfs.core found cached object: [{'kind': 'storage#object', 'id': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zattrs/1517251342776888', 'selfLink': 'https://www.googleapis.com/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Fcrs%2F.zattrs', 'name': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zattrs', 'bucket': 'pangeo-data', 'generation': '1517251342776888', 'metageneration': '1', 'timeCreated': '2018-01-29T18:42:22.739Z', 'updated': '2018-01-29T18:42:22.739Z', 'storageClass': 'REGIONAL', 'timeStorageClassUpdated': '2018-01-29T18:42:22.739Z', 'size': 355, 'md5Hash': 'DHnGx5uaaPQ8oW8VoY2K+A==', 'mediaLink': 'https://www.googleapis.com/download/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Fcrs%2F.zattrs?generation=1517251342776888&alt=media', 'crc32c': 'EJcmOA==', 'etag': 'CLj0yNrp/dgCEAE=', 'path': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zattrs'}]
1518772143.497 DEBUG gcsfs.core __enter__(args=(), kwargs={})
1518772143.498 DEBUG gcsfs.core _fetch(args=(0, 355), kwargs={})
--- Logging error ---
Traceback (most recent call last):
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 992, in emit
    msg = self.format(record)
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 838, in format
    return fmt.format(record)
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 575, in format
    record.message = record.getMessage()
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 338, in getMessage
    msg = msg % self.args
TypeError: not all arguments converted during string formatting
Call stack:
  File "/opt/conda/lib/python3.6/runpy.py", line 193, in _run_module_as_main
    "__main__", mod_spec)
  File "/opt/conda/lib/python3.6/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/__main__.py", line 3, in <module>
    app.launch_new_instance()
  File "/opt/conda/lib/python3.6/site-packages/traitlets/config/application.py", line 658, in launch_instance
    app.start()
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelapp.py", line 477, in start
    ioloop.IOLoop.instance().start()
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/ioloop.py", line 177, in start
    super(ZMQIOLoop, self).start()
  File "/opt/conda/lib/python3.6/site-packages/tornado/ioloop.py", line 888, in start
    handler_func(fd_obj, events)
  File "/opt/conda/lib/python3.6/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    return fn(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 440, in _handle_events
    self._handle_recv()
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 472, in _handle_recv
    self._run_callback(callback, msg)
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 414, in _run_callback
    callback(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    return fn(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 283, in dispatcher
    return self.dispatch_shell(stream, msg)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 235, in dispatch_shell
    handler(stream, idents, msg)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 399, in execute_request
    user_expressions, allow_stdin)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/ipkernel.py", line 196, in do_execute
    res = shell.run_cell(code, store_history=store_history, silent=silent)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/zmqshell.py", line 533, in run_cell
    return super(ZMQInteractiveShell, self).run_cell(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2728, in run_cell
    interactivity=interactivity, compiler=compiler, result=result)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2850, in run_ast_nodes
    if self.run_code(code, result):
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2910, in run_code
    exec(code_obj, self.user_global_ns, self.user_ns)
  File "<ipython-input-9-051a91e550af>", line 5, in <module>
    get_ipython().run_line_magic('time', 'ds = xr.open_zarr(gcsmap)')
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2095, in run_line_magic
    result = fn(*args,**kwargs)
  File "<decorator-gen-62>", line 2, in time
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/magic.py", line 187, in <lambda>
    call = lambda f, *a, **k: f(*a, **k)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/magics/execution.py", line 1238, in time
    exec(code, glob, local_ns)
  File "<timed exec>", line 1, in <module>
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 473, in open_zarr
    ds = maybe_decode_store(zarr_store)
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 461, in maybe_decode_store
    drop_variables=drop_variables)
  File "/opt/conda/lib/python3.6/site-packages/xarray/conventions.py", line 598, in decode_cf
    vars, attrs = obj.load()
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/common.py", line 133, in load
    for k, v in self.get_variables().items())
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 314, in get_variables
    for k, v in self.ds.arrays())
  File "/opt/conda/lib/python3.6/site-packages/xarray/core/utils.py", line 309, in FrozenOrderedDict
    return Frozen(OrderedDict(*args, **kwargs))
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 314, in <genexpr>
    for k, v in self.ds.arrays())
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 300, in open_store_variable
    _DIMENSION_KEY)
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 196, in _get_zarr_dims_and_attrs
    dimensions = zarr_obj.attrs[dimension_key]
  File "/opt/conda/lib/python3.6/site-packages/zarr/attrs.py", line 67, in __getitem__
    return self.asdict()[item]
  File "/opt/conda/lib/python3.6/site-packages/zarr/attrs.py", line 53, in asdict
    d = self._get_nosync()
  File "/opt/conda/lib/python3.6/site-packages/zarr/attrs.py", line 42, in _get_nosync
    data = self.store[self.key]
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/mapping.py", line 68, in __getitem__
    result = f.read()
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1280, in read
    self._fetch(self.loc, self.loc + length)
  File "<decorator-gen-156>", line 2, in _fetch
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 48, in _tracemethod
    return f(self, *args, **kwargs)
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1239, in _fetch
    self.end)
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1344, in _fetch_range
    logger.debug("Fetch: {}, {}-{}", obj_dict['name'], start, end)
Message: 'Fetch: {}, {}-{}'
Arguments: ('dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zattrs', 0, 10485760)
1518772143.616 DEBUG gcsfs.core __exit__(args=(None, None, None), kwargs={})
1518772143.617 DEBUG gcsfs.core close(args=(), kwargs={})
1518772143.618 DEBUG gcsfs.core __del__(args=(), kwargs={})
1518772143.619 DEBUG gcsfs.core close(args=(), kwargs={})
1518772143.621 DEBUG gcsfs.core exists(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/.zarray',), kwargs={})
1518772143.624 DEBUG gcsfs.core info(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/.zarray',), kwargs={})
1518772143.626 DEBUG gcsfs.core _get_object(pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/.zarray)
1518772143.627 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/',), kwargs={})
1518772143.628 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/
1518772143.629 DEBUG gcsfs.core found cached object: [{'kind': 'storage#object', 'id': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/.zarray/1517251482955304', 'selfLink': 'https://www.googleapis.com/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Ferr%2F.zarray', 'name': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/.zarray', 'bucket': 'pangeo-data', 'generation': '1517251482955304', 'metageneration': '1', 'timeCreated': '2018-01-29T18:44:42.929Z', 'updated': '2018-01-29T18:44:42.929Z', 'storageClass': 'REGIONAL', 'timeStorageClassUpdated': '2018-01-29T18:44:42.929Z', 'size': 371, 'md5Hash': 'ijnyP1l9SpsV3qtG1T9Uig==', 'mediaLink': 'https://www.googleapis.com/download/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Ferr%2F.zarray?generation=1517251482955304&alt=media', 'crc32c': 'HDOHbA==', 'etag': 'CKjctJ3q/dgCEAE=', 'path': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/.zarray'}]
1518772143.630 DEBUG gcsfs.core open(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/.zarray', 'rb', None, None, None, None), kwargs={})
1518772143.631 DEBUG gcsfs.core __init__(args=(<gcsfs.core.GCSFileSystem object at 0x7f8d67f895c0>, 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/.zarray', 'rb', 5242880, None, 'none', None), kwargs={})
1518772143.632 DEBUG gcsfs.core info(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/.zarray',), kwargs={})
1518772143.632 DEBUG gcsfs.core _get_object(pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/.zarray)
1518772143.633 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/',), kwargs={})
1518772143.634 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/
1518772143.635 DEBUG gcsfs.core found cached object: [{'kind': 'storage#object', 'id': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/.zarray/1517251482955304', 'selfLink': 'https://www.googleapis.com/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Ferr%2F.zarray', 'name': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/.zarray', 'bucket': 'pangeo-data', 'generation': '1517251482955304', 'metageneration': '1', 'timeCreated': '2018-01-29T18:44:42.929Z', 'updated': '2018-01-29T18:44:42.929Z', 'storageClass': 'REGIONAL', 'timeStorageClassUpdated': '2018-01-29T18:44:42.929Z', 'size': 371, 'md5Hash': 'ijnyP1l9SpsV3qtG1T9Uig==', 'mediaLink': 'https://www.googleapis.com/download/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Ferr%2F.zarray?generation=1517251482955304&alt=media', 'crc32c': 'HDOHbA==', 'etag': 'CKjctJ3q/dgCEAE=', 'path': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/.zarray'}]
1518772143.637 DEBUG gcsfs.core __enter__(args=(), kwargs={})
1518772143.638 DEBUG gcsfs.core _fetch(args=(0, 371), kwargs={})
--- Logging error ---
Traceback (most recent call last):
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 992, in emit
    msg = self.format(record)
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 838, in format
    return fmt.format(record)
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 575, in format
    record.message = record.getMessage()
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 338, in getMessage
    msg = msg % self.args
TypeError: not all arguments converted during string formatting
Call stack:
  File "/opt/conda/lib/python3.6/runpy.py", line 193, in _run_module_as_main
    "__main__", mod_spec)
  File "/opt/conda/lib/python3.6/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/__main__.py", line 3, in <module>
    app.launch_new_instance()
  File "/opt/conda/lib/python3.6/site-packages/traitlets/config/application.py", line 658, in launch_instance
    app.start()
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelapp.py", line 477, in start
    ioloop.IOLoop.instance().start()
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/ioloop.py", line 177, in start
    super(ZMQIOLoop, self).start()
  File "/opt/conda/lib/python3.6/site-packages/tornado/ioloop.py", line 888, in start
    handler_func(fd_obj, events)
  File "/opt/conda/lib/python3.6/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    return fn(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 440, in _handle_events
    self._handle_recv()
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 472, in _handle_recv
    self._run_callback(callback, msg)
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 414, in _run_callback
    callback(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    return fn(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 283, in dispatcher
    return self.dispatch_shell(stream, msg)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 235, in dispatch_shell
    handler(stream, idents, msg)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 399, in execute_request
    user_expressions, allow_stdin)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/ipkernel.py", line 196, in do_execute
    res = shell.run_cell(code, store_history=store_history, silent=silent)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/zmqshell.py", line 533, in run_cell
    return super(ZMQInteractiveShell, self).run_cell(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2728, in run_cell
    interactivity=interactivity, compiler=compiler, result=result)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2850, in run_ast_nodes
    if self.run_code(code, result):
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2910, in run_code
    exec(code_obj, self.user_global_ns, self.user_ns)
  File "<ipython-input-9-051a91e550af>", line 5, in <module>
    get_ipython().run_line_magic('time', 'ds = xr.open_zarr(gcsmap)')
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2095, in run_line_magic
    result = fn(*args,**kwargs)
  File "<decorator-gen-62>", line 2, in time
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/magic.py", line 187, in <lambda>
    call = lambda f, *a, **k: f(*a, **k)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/magics/execution.py", line 1238, in time
    exec(code, glob, local_ns)
  File "<timed exec>", line 1, in <module>
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 473, in open_zarr
    ds = maybe_decode_store(zarr_store)
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 461, in maybe_decode_store
    drop_variables=drop_variables)
  File "/opt/conda/lib/python3.6/site-packages/xarray/conventions.py", line 598, in decode_cf
    vars, attrs = obj.load()
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/common.py", line 133, in load
    for k, v in self.get_variables().items())
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 314, in get_variables
    for k, v in self.ds.arrays())
  File "/opt/conda/lib/python3.6/site-packages/xarray/core/utils.py", line 309, in FrozenOrderedDict
    return Frozen(OrderedDict(*args, **kwargs))
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 313, in <genexpr>
    return FrozenOrderedDict((k, self.open_store_variable(k, v))
  File "/opt/conda/lib/python3.6/site-packages/zarr/hierarchy.py", line 458, in arrays
    synchronizer=self._synchronizer)
  File "/opt/conda/lib/python3.6/site-packages/zarr/core.py", line 123, in __init__
    self._load_metadata()
  File "/opt/conda/lib/python3.6/site-packages/zarr/core.py", line 140, in _load_metadata
    self._load_metadata_nosync()
  File "/opt/conda/lib/python3.6/site-packages/zarr/core.py", line 149, in _load_metadata_nosync
    meta_bytes = self._store[mkey]
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/mapping.py", line 68, in __getitem__
    result = f.read()
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1280, in read
    self._fetch(self.loc, self.loc + length)
  File "<decorator-gen-156>", line 2, in _fetch
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 48, in _tracemethod
    return f(self, *args, **kwargs)
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1239, in _fetch
    self.end)
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1344, in _fetch_range
    logger.debug("Fetch: {}, {}-{}", obj_dict['name'], start, end)
Message: 'Fetch: {}, {}-{}'
Arguments: ('dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/.zarray', 0, 10485760)
1518772143.776 DEBUG gcsfs.core __exit__(args=(None, None, None), kwargs={})
1518772143.778 DEBUG gcsfs.core close(args=(), kwargs={})
1518772143.780 DEBUG gcsfs.core __del__(args=(), kwargs={})
1518772143.785 DEBUG gcsfs.core close(args=(), kwargs={})
1518772143.787 DEBUG gcsfs.core exists(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/.zarray',), kwargs={})
1518772143.789 DEBUG gcsfs.core info(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/.zarray',), kwargs={})
1518772143.790 DEBUG gcsfs.core _get_object(pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/.zarray)
1518772143.791 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/',), kwargs={})
1518772143.792 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/
1518772143.794 DEBUG gcsfs.core found cached object: [{'kind': 'storage#object', 'id': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/.zarray/1517251482955304', 'selfLink': 'https://www.googleapis.com/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Ferr%2F.zarray', 'name': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/.zarray', 'bucket': 'pangeo-data', 'generation': '1517251482955304', 'metageneration': '1', 'timeCreated': '2018-01-29T18:44:42.929Z', 'updated': '2018-01-29T18:44:42.929Z', 'storageClass': 'REGIONAL', 'timeStorageClassUpdated': '2018-01-29T18:44:42.929Z', 'size': 371, 'md5Hash': 'ijnyP1l9SpsV3qtG1T9Uig==', 'mediaLink': 'https://www.googleapis.com/download/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Ferr%2F.zarray?generation=1517251482955304&alt=media', 'crc32c': 'HDOHbA==', 'etag': 'CKjctJ3q/dgCEAE=', 'path': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/.zarray'}]
1518772143.796 DEBUG gcsfs.core open(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/.zarray', 'rb', None, None, None, None), kwargs={})
1518772143.798 DEBUG gcsfs.core __init__(args=(<gcsfs.core.GCSFileSystem object at 0x7f8d67f895c0>, 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/.zarray', 'rb', 5242880, None, 'none', None), kwargs={})
1518772143.799 DEBUG gcsfs.core info(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/.zarray',), kwargs={})
1518772143.800 DEBUG gcsfs.core _get_object(pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/.zarray)
1518772143.801 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/',), kwargs={})
1518772143.801 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/
1518772143.803 DEBUG gcsfs.core found cached object: [{'kind': 'storage#object', 'id': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/.zarray/1517251482955304', 'selfLink': 'https://www.googleapis.com/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Ferr%2F.zarray', 'name': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/.zarray', 'bucket': 'pangeo-data', 'generation': '1517251482955304', 'metageneration': '1', 'timeCreated': '2018-01-29T18:44:42.929Z', 'updated': '2018-01-29T18:44:42.929Z', 'storageClass': 'REGIONAL', 'timeStorageClassUpdated': '2018-01-29T18:44:42.929Z', 'size': 371, 'md5Hash': 'ijnyP1l9SpsV3qtG1T9Uig==', 'mediaLink': 'https://www.googleapis.com/download/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Ferr%2F.zarray?generation=1517251482955304&alt=media', 'crc32c': 'HDOHbA==', 'etag': 'CKjctJ3q/dgCEAE=', 'path': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/.zarray'}]
1518772143.804 DEBUG gcsfs.core __enter__(args=(), kwargs={})
1518772143.805 DEBUG gcsfs.core _fetch(args=(0, 371), kwargs={})
--- Logging error ---
Traceback (most recent call last):
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 992, in emit
    msg = self.format(record)
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 838, in format
    return fmt.format(record)
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 575, in format
    record.message = record.getMessage()
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 338, in getMessage
    msg = msg % self.args
TypeError: not all arguments converted during string formatting
Call stack:
  File "/opt/conda/lib/python3.6/runpy.py", line 193, in _run_module_as_main
    "__main__", mod_spec)
  File "/opt/conda/lib/python3.6/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/__main__.py", line 3, in <module>
    app.launch_new_instance()
  File "/opt/conda/lib/python3.6/site-packages/traitlets/config/application.py", line 658, in launch_instance
    app.start()
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelapp.py", line 477, in start
    ioloop.IOLoop.instance().start()
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/ioloop.py", line 177, in start
    super(ZMQIOLoop, self).start()
  File "/opt/conda/lib/python3.6/site-packages/tornado/ioloop.py", line 888, in start
    handler_func(fd_obj, events)
  File "/opt/conda/lib/python3.6/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    return fn(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 440, in _handle_events
    self._handle_recv()
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 472, in _handle_recv
    self._run_callback(callback, msg)
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 414, in _run_callback
    callback(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    return fn(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 283, in dispatcher
    return self.dispatch_shell(stream, msg)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 235, in dispatch_shell
    handler(stream, idents, msg)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 399, in execute_request
    user_expressions, allow_stdin)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/ipkernel.py", line 196, in do_execute
    res = shell.run_cell(code, store_history=store_history, silent=silent)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/zmqshell.py", line 533, in run_cell
    return super(ZMQInteractiveShell, self).run_cell(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2728, in run_cell
    interactivity=interactivity, compiler=compiler, result=result)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2850, in run_ast_nodes
    if self.run_code(code, result):
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2910, in run_code
    exec(code_obj, self.user_global_ns, self.user_ns)
  File "<ipython-input-9-051a91e550af>", line 5, in <module>
    get_ipython().run_line_magic('time', 'ds = xr.open_zarr(gcsmap)')
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2095, in run_line_magic
    result = fn(*args,**kwargs)
  File "<decorator-gen-62>", line 2, in time
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/magic.py", line 187, in <lambda>
    call = lambda f, *a, **k: f(*a, **k)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/magics/execution.py", line 1238, in time
    exec(code, glob, local_ns)
  File "<timed exec>", line 1, in <module>
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 473, in open_zarr
    ds = maybe_decode_store(zarr_store)
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 461, in maybe_decode_store
    drop_variables=drop_variables)
  File "/opt/conda/lib/python3.6/site-packages/xarray/conventions.py", line 598, in decode_cf
    vars, attrs = obj.load()
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/common.py", line 133, in load
    for k, v in self.get_variables().items())
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 314, in get_variables
    for k, v in self.ds.arrays())
  File "/opt/conda/lib/python3.6/site-packages/xarray/core/utils.py", line 309, in FrozenOrderedDict
    return Frozen(OrderedDict(*args, **kwargs))
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 314, in <genexpr>
    for k, v in self.ds.arrays())
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 298, in open_store_variable
    data = indexing.LazilyIndexedArray(ZarrArrayWrapper(name, self))
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 76, in __init__
    array = self.get_array()
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 83, in get_array
    return self.datastore.ds[self.variable_name]
  File "/opt/conda/lib/python3.6/site-packages/zarr/hierarchy.py", line 328, in __getitem__
    synchronizer=self._synchronizer, cache_attrs=self.attrs.cache)
  File "/opt/conda/lib/python3.6/site-packages/zarr/core.py", line 123, in __init__
    self._load_metadata()
  File "/opt/conda/lib/python3.6/site-packages/zarr/core.py", line 140, in _load_metadata
    self._load_metadata_nosync()
  File "/opt/conda/lib/python3.6/site-packages/zarr/core.py", line 149, in _load_metadata_nosync
    meta_bytes = self._store[mkey]
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/mapping.py", line 68, in __getitem__
    result = f.read()
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1280, in read
    self._fetch(self.loc, self.loc + length)
  File "<decorator-gen-156>", line 2, in _fetch
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 48, in _tracemethod
    return f(self, *args, **kwargs)
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1239, in _fetch
    self.end)
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1344, in _fetch_range
    logger.debug("Fetch: {}, {}-{}", obj_dict['name'], start, end)
Message: 'Fetch: {}, {}-{}'
Arguments: ('dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/.zarray', 0, 10485760)
1518772143.850 DEBUG gcsfs.core __exit__(args=(None, None, None), kwargs={})
1518772143.852 DEBUG gcsfs.core close(args=(), kwargs={})
1518772143.853 DEBUG gcsfs.core __del__(args=(), kwargs={})
1518772143.854 DEBUG gcsfs.core close(args=(), kwargs={})
1518772143.855 DEBUG gcsfs.core open(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/.zattrs', 'rb', None, None, None, None), kwargs={})
1518772143.856 DEBUG gcsfs.core __init__(args=(<gcsfs.core.GCSFileSystem object at 0x7f8d67f895c0>, 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/.zattrs', 'rb', 5242880, None, 'none', None), kwargs={})
1518772143.857 DEBUG gcsfs.core info(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/.zattrs',), kwargs={})
1518772143.858 DEBUG gcsfs.core _get_object(pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/.zattrs)
1518772143.859 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/',), kwargs={})
1518772143.860 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/
1518772143.861 DEBUG gcsfs.core found cached object: [{'kind': 'storage#object', 'id': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/.zattrs/1517251483585753', 'selfLink': 'https://www.googleapis.com/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Ferr%2F.zattrs', 'name': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/.zattrs', 'bucket': 'pangeo-data', 'generation': '1517251483585753', 'metageneration': '1', 'timeCreated': '2018-01-29T18:44:43.566Z', 'updated': '2018-01-29T18:44:43.566Z', 'storageClass': 'REGIONAL', 'timeStorageClassUpdated': '2018-01-29T18:44:43.566Z', 'size': 490, 'md5Hash': 'Qr3oRqVLkZ7ILCIeQsN6kA==', 'mediaLink': 'https://www.googleapis.com/download/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Ferr%2F.zattrs?generation=1517251483585753&alt=media', 'crc32c': 'ciCk1w==', 'etag': 'CNmZ253q/dgCEAE=', 'path': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/.zattrs'}]
1518772143.862 DEBUG gcsfs.core __enter__(args=(), kwargs={})
1518772143.863 DEBUG gcsfs.core _fetch(args=(0, 490), kwargs={})
--- Logging error ---
Traceback (most recent call last):
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 992, in emit
    msg = self.format(record)
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 838, in format
    return fmt.format(record)
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 575, in format
    record.message = record.getMessage()
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 338, in getMessage
    msg = msg % self.args
TypeError: not all arguments converted during string formatting
Call stack:
  File "/opt/conda/lib/python3.6/runpy.py", line 193, in _run_module_as_main
    "__main__", mod_spec)
  File "/opt/conda/lib/python3.6/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/__main__.py", line 3, in <module>
    app.launch_new_instance()
  File "/opt/conda/lib/python3.6/site-packages/traitlets/config/application.py", line 658, in launch_instance
    app.start()
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelapp.py", line 477, in start
    ioloop.IOLoop.instance().start()
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/ioloop.py", line 177, in start
    super(ZMQIOLoop, self).start()
  File "/opt/conda/lib/python3.6/site-packages/tornado/ioloop.py", line 888, in start
    handler_func(fd_obj, events)
  File "/opt/conda/lib/python3.6/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    return fn(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 440, in _handle_events
    self._handle_recv()
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 472, in _handle_recv
    self._run_callback(callback, msg)
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 414, in _run_callback
    callback(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    return fn(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 283, in dispatcher
    return self.dispatch_shell(stream, msg)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 235, in dispatch_shell
    handler(stream, idents, msg)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 399, in execute_request
    user_expressions, allow_stdin)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/ipkernel.py", line 196, in do_execute
    res = shell.run_cell(code, store_history=store_history, silent=silent)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/zmqshell.py", line 533, in run_cell
    return super(ZMQInteractiveShell, self).run_cell(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2728, in run_cell
    interactivity=interactivity, compiler=compiler, result=result)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2850, in run_ast_nodes
    if self.run_code(code, result):
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2910, in run_code
    exec(code_obj, self.user_global_ns, self.user_ns)
  File "<ipython-input-9-051a91e550af>", line 5, in <module>
    get_ipython().run_line_magic('time', 'ds = xr.open_zarr(gcsmap)')
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2095, in run_line_magic
    result = fn(*args,**kwargs)
  File "<decorator-gen-62>", line 2, in time
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/magic.py", line 187, in <lambda>
    call = lambda f, *a, **k: f(*a, **k)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/magics/execution.py", line 1238, in time
    exec(code, glob, local_ns)
  File "<timed exec>", line 1, in <module>
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 473, in open_zarr
    ds = maybe_decode_store(zarr_store)
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 461, in maybe_decode_store
    drop_variables=drop_variables)
  File "/opt/conda/lib/python3.6/site-packages/xarray/conventions.py", line 598, in decode_cf
    vars, attrs = obj.load()
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/common.py", line 133, in load
    for k, v in self.get_variables().items())
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 314, in get_variables
    for k, v in self.ds.arrays())
  File "/opt/conda/lib/python3.6/site-packages/xarray/core/utils.py", line 309, in FrozenOrderedDict
    return Frozen(OrderedDict(*args, **kwargs))
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 314, in <genexpr>
    for k, v in self.ds.arrays())
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 300, in open_store_variable
    _DIMENSION_KEY)
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 196, in _get_zarr_dims_and_attrs
    dimensions = zarr_obj.attrs[dimension_key]
  File "/opt/conda/lib/python3.6/site-packages/zarr/attrs.py", line 67, in __getitem__
    return self.asdict()[item]
  File "/opt/conda/lib/python3.6/site-packages/zarr/attrs.py", line 53, in asdict
    d = self._get_nosync()
  File "/opt/conda/lib/python3.6/site-packages/zarr/attrs.py", line 42, in _get_nosync
    data = self.store[self.key]
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/mapping.py", line 68, in __getitem__
    result = f.read()
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1280, in read
    self._fetch(self.loc, self.loc + length)
  File "<decorator-gen-156>", line 2, in _fetch
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 48, in _tracemethod
    return f(self, *args, **kwargs)
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1239, in _fetch
    self.end)
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1344, in _fetch_range
    logger.debug("Fetch: {}, {}-{}", obj_dict['name'], start, end)
Message: 'Fetch: {}, {}-{}'
Arguments: ('dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/err/.zattrs', 0, 10485760)
1518772143.968 DEBUG gcsfs.core __exit__(args=(None, None, None), kwargs={})
1518772143.971 DEBUG gcsfs.core close(args=(), kwargs={})
1518772143.972 DEBUG gcsfs.core __del__(args=(), kwargs={})
1518772143.973 DEBUG gcsfs.core close(args=(), kwargs={})
1518772143.975 DEBUG gcsfs.core exists(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/.zarray',), kwargs={})
1518772143.976 DEBUG gcsfs.core info(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/.zarray',), kwargs={})
1518772143.977 DEBUG gcsfs.core _get_object(pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/.zarray)
1518772143.978 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/',), kwargs={})
1518772143.980 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/
1518772143.981 DEBUG gcsfs.core found cached object: [{'kind': 'storage#object', 'id': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/.zarray/1517251435771959', 'selfLink': 'https://www.googleapis.com/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Flat_bnds%2F.zarray', 'name': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/.zarray', 'bucket': 'pangeo-data', 'generation': '1517251435771959', 'metageneration': '1', 'timeCreated': '2018-01-29T18:43:55.752Z', 'updated': '2018-01-29T18:43:55.752Z', 'storageClass': 'REGIONAL', 'timeStorageClassUpdated': '2018-01-29T18:43:55.752Z', 'size': 365, 'md5Hash': '//1f4qWjvbRw7szO7BaQdw==', 'mediaLink': 'https://www.googleapis.com/download/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Flat_bnds%2F.zarray?generation=1517251435771959&alt=media', 'crc32c': 'jZJyUA==', 'etag': 'CLfw9Ibq/dgCEAE=', 'path': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/.zarray'}]
1518772143.982 DEBUG gcsfs.core open(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/.zarray', 'rb', None, None, None, None), kwargs={})
1518772143.983 DEBUG gcsfs.core __init__(args=(<gcsfs.core.GCSFileSystem object at 0x7f8d67f895c0>, 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/.zarray', 'rb', 5242880, None, 'none', None), kwargs={})
1518772143.984 DEBUG gcsfs.core info(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/.zarray',), kwargs={})
1518772143.985 DEBUG gcsfs.core _get_object(pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/.zarray)
1518772143.987 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/',), kwargs={})
1518772143.987 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/
1518772143.989 DEBUG gcsfs.core found cached object: [{'kind': 'storage#object', 'id': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/.zarray/1517251435771959', 'selfLink': 'https://www.googleapis.com/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Flat_bnds%2F.zarray', 'name': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/.zarray', 'bucket': 'pangeo-data', 'generation': '1517251435771959', 'metageneration': '1', 'timeCreated': '2018-01-29T18:43:55.752Z', 'updated': '2018-01-29T18:43:55.752Z', 'storageClass': 'REGIONAL', 'timeStorageClassUpdated': '2018-01-29T18:43:55.752Z', 'size': 365, 'md5Hash': '//1f4qWjvbRw7szO7BaQdw==', 'mediaLink': 'https://www.googleapis.com/download/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Flat_bnds%2F.zarray?generation=1517251435771959&alt=media', 'crc32c': 'jZJyUA==', 'etag': 'CLfw9Ibq/dgCEAE=', 'path': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/.zarray'}]
1518772143.990 DEBUG gcsfs.core __enter__(args=(), kwargs={})
1518772143.991 DEBUG gcsfs.core _fetch(args=(0, 365), kwargs={})
--- Logging error ---
Traceback (most recent call last):
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 992, in emit
    msg = self.format(record)
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 838, in format
    return fmt.format(record)
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 575, in format
    record.message = record.getMessage()
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 338, in getMessage
    msg = msg % self.args
TypeError: not all arguments converted during string formatting
Call stack:
  File "/opt/conda/lib/python3.6/runpy.py", line 193, in _run_module_as_main
    "__main__", mod_spec)
  File "/opt/conda/lib/python3.6/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/__main__.py", line 3, in <module>
    app.launch_new_instance()
  File "/opt/conda/lib/python3.6/site-packages/traitlets/config/application.py", line 658, in launch_instance
    app.start()
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelapp.py", line 477, in start
    ioloop.IOLoop.instance().start()
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/ioloop.py", line 177, in start
    super(ZMQIOLoop, self).start()
  File "/opt/conda/lib/python3.6/site-packages/tornado/ioloop.py", line 888, in start
    handler_func(fd_obj, events)
  File "/opt/conda/lib/python3.6/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    return fn(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 440, in _handle_events
    self._handle_recv()
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 472, in _handle_recv
    self._run_callback(callback, msg)
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 414, in _run_callback
    callback(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    return fn(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 283, in dispatcher
    return self.dispatch_shell(stream, msg)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 235, in dispatch_shell
    handler(stream, idents, msg)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 399, in execute_request
    user_expressions, allow_stdin)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/ipkernel.py", line 196, in do_execute
    res = shell.run_cell(code, store_history=store_history, silent=silent)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/zmqshell.py", line 533, in run_cell
    return super(ZMQInteractiveShell, self).run_cell(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2728, in run_cell
    interactivity=interactivity, compiler=compiler, result=result)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2850, in run_ast_nodes
    if self.run_code(code, result):
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2910, in run_code
    exec(code_obj, self.user_global_ns, self.user_ns)
  File "<ipython-input-9-051a91e550af>", line 5, in <module>
    get_ipython().run_line_magic('time', 'ds = xr.open_zarr(gcsmap)')
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2095, in run_line_magic
    result = fn(*args,**kwargs)
  File "<decorator-gen-62>", line 2, in time
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/magic.py", line 187, in <lambda>
    call = lambda f, *a, **k: f(*a, **k)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/magics/execution.py", line 1238, in time
    exec(code, glob, local_ns)
  File "<timed exec>", line 1, in <module>
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 473, in open_zarr
    ds = maybe_decode_store(zarr_store)
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 461, in maybe_decode_store
    drop_variables=drop_variables)
  File "/opt/conda/lib/python3.6/site-packages/xarray/conventions.py", line 598, in decode_cf
    vars, attrs = obj.load()
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/common.py", line 133, in load
    for k, v in self.get_variables().items())
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 314, in get_variables
    for k, v in self.ds.arrays())
  File "/opt/conda/lib/python3.6/site-packages/xarray/core/utils.py", line 309, in FrozenOrderedDict
    return Frozen(OrderedDict(*args, **kwargs))
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 313, in <genexpr>
    return FrozenOrderedDict((k, self.open_store_variable(k, v))
  File "/opt/conda/lib/python3.6/site-packages/zarr/hierarchy.py", line 458, in arrays
    synchronizer=self._synchronizer)
  File "/opt/conda/lib/python3.6/site-packages/zarr/core.py", line 123, in __init__
    self._load_metadata()
  File "/opt/conda/lib/python3.6/site-packages/zarr/core.py", line 140, in _load_metadata
    self._load_metadata_nosync()
  File "/opt/conda/lib/python3.6/site-packages/zarr/core.py", line 149, in _load_metadata_nosync
    meta_bytes = self._store[mkey]
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/mapping.py", line 68, in __getitem__
    result = f.read()
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1280, in read
    self._fetch(self.loc, self.loc + length)
  File "<decorator-gen-156>", line 2, in _fetch
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 48, in _tracemethod
    return f(self, *args, **kwargs)
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1239, in _fetch
    self.end)
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1344, in _fetch_range
    logger.debug("Fetch: {}, {}-{}", obj_dict['name'], start, end)
Message: 'Fetch: {}, {}-{}'
Arguments: ('dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/.zarray', 0, 10485760)
1518772144.054 DEBUG gcsfs.core __exit__(args=(None, None, None), kwargs={})
1518772144.056 DEBUG gcsfs.core close(args=(), kwargs={})
1518772144.060 DEBUG gcsfs.core __del__(args=(), kwargs={})
1518772144.062 DEBUG gcsfs.core close(args=(), kwargs={})
1518772144.065 DEBUG gcsfs.core exists(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/.zarray',), kwargs={})
1518772144.067 DEBUG gcsfs.core info(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/.zarray',), kwargs={})
1518772144.069 DEBUG gcsfs.core _get_object(pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/.zarray)
1518772144.072 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/',), kwargs={})
1518772144.073 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/
1518772144.075 DEBUG gcsfs.core found cached object: [{'kind': 'storage#object', 'id': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/.zarray/1517251435771959', 'selfLink': 'https://www.googleapis.com/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Flat_bnds%2F.zarray', 'name': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/.zarray', 'bucket': 'pangeo-data', 'generation': '1517251435771959', 'metageneration': '1', 'timeCreated': '2018-01-29T18:43:55.752Z', 'updated': '2018-01-29T18:43:55.752Z', 'storageClass': 'REGIONAL', 'timeStorageClassUpdated': '2018-01-29T18:43:55.752Z', 'size': 365, 'md5Hash': '//1f4qWjvbRw7szO7BaQdw==', 'mediaLink': 'https://www.googleapis.com/download/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Flat_bnds%2F.zarray?generation=1517251435771959&alt=media', 'crc32c': 'jZJyUA==', 'etag': 'CLfw9Ibq/dgCEAE=', 'path': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/.zarray'}]
1518772144.076 DEBUG gcsfs.core open(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/.zarray', 'rb', None, None, None, None), kwargs={})
1518772144.077 DEBUG gcsfs.core __init__(args=(<gcsfs.core.GCSFileSystem object at 0x7f8d67f895c0>, 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/.zarray', 'rb', 5242880, None, 'none', None), kwargs={})
1518772144.078 DEBUG gcsfs.core info(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/.zarray',), kwargs={})
1518772144.079 DEBUG gcsfs.core _get_object(pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/.zarray)
1518772144.080 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/',), kwargs={})
1518772144.081 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/
1518772144.083 DEBUG gcsfs.core found cached object: [{'kind': 'storage#object', 'id': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/.zarray/1517251435771959', 'selfLink': 'https://www.googleapis.com/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Flat_bnds%2F.zarray', 'name': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/.zarray', 'bucket': 'pangeo-data', 'generation': '1517251435771959', 'metageneration': '1', 'timeCreated': '2018-01-29T18:43:55.752Z', 'updated': '2018-01-29T18:43:55.752Z', 'storageClass': 'REGIONAL', 'timeStorageClassUpdated': '2018-01-29T18:43:55.752Z', 'size': 365, 'md5Hash': '//1f4qWjvbRw7szO7BaQdw==', 'mediaLink': 'https://www.googleapis.com/download/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Flat_bnds%2F.zarray?generation=1517251435771959&alt=media', 'crc32c': 'jZJyUA==', 'etag': 'CLfw9Ibq/dgCEAE=', 'path': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/.zarray'}]
1518772144.084 DEBUG gcsfs.core __enter__(args=(), kwargs={})
1518772144.085 DEBUG gcsfs.core _fetch(args=(0, 365), kwargs={})
--- Logging error ---
Traceback (most recent call last):
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 992, in emit
    msg = self.format(record)
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 838, in format
    return fmt.format(record)
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 575, in format
    record.message = record.getMessage()
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 338, in getMessage
    msg = msg % self.args
TypeError: not all arguments converted during string formatting
Call stack:
  File "/opt/conda/lib/python3.6/runpy.py", line 193, in _run_module_as_main
    "__main__", mod_spec)
  File "/opt/conda/lib/python3.6/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/__main__.py", line 3, in <module>
    app.launch_new_instance()
  File "/opt/conda/lib/python3.6/site-packages/traitlets/config/application.py", line 658, in launch_instance
    app.start()
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelapp.py", line 477, in start
    ioloop.IOLoop.instance().start()
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/ioloop.py", line 177, in start
    super(ZMQIOLoop, self).start()
  File "/opt/conda/lib/python3.6/site-packages/tornado/ioloop.py", line 888, in start
    handler_func(fd_obj, events)
  File "/opt/conda/lib/python3.6/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    return fn(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 440, in _handle_events
    self._handle_recv()
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 472, in _handle_recv
    self._run_callback(callback, msg)
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 414, in _run_callback
    callback(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    return fn(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 283, in dispatcher
    return self.dispatch_shell(stream, msg)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 235, in dispatch_shell
    handler(stream, idents, msg)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 399, in execute_request
    user_expressions, allow_stdin)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/ipkernel.py", line 196, in do_execute
    res = shell.run_cell(code, store_history=store_history, silent=silent)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/zmqshell.py", line 533, in run_cell
    return super(ZMQInteractiveShell, self).run_cell(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2728, in run_cell
    interactivity=interactivity, compiler=compiler, result=result)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2850, in run_ast_nodes
    if self.run_code(code, result):
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2910, in run_code
    exec(code_obj, self.user_global_ns, self.user_ns)
  File "<ipython-input-9-051a91e550af>", line 5, in <module>
    get_ipython().run_line_magic('time', 'ds = xr.open_zarr(gcsmap)')
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2095, in run_line_magic
    result = fn(*args,**kwargs)
  File "<decorator-gen-62>", line 2, in time
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/magic.py", line 187, in <lambda>
    call = lambda f, *a, **k: f(*a, **k)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/magics/execution.py", line 1238, in time
    exec(code, glob, local_ns)
  File "<timed exec>", line 1, in <module>
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 473, in open_zarr
    ds = maybe_decode_store(zarr_store)
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 461, in maybe_decode_store
    drop_variables=drop_variables)
  File "/opt/conda/lib/python3.6/site-packages/xarray/conventions.py", line 598, in decode_cf
    vars, attrs = obj.load()
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/common.py", line 133, in load
    for k, v in self.get_variables().items())
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 314, in get_variables
    for k, v in self.ds.arrays())
  File "/opt/conda/lib/python3.6/site-packages/xarray/core/utils.py", line 309, in FrozenOrderedDict
    return Frozen(OrderedDict(*args, **kwargs))
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 314, in <genexpr>
    for k, v in self.ds.arrays())
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 298, in open_store_variable
    data = indexing.LazilyIndexedArray(ZarrArrayWrapper(name, self))
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 76, in __init__
    array = self.get_array()
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 83, in get_array
    return self.datastore.ds[self.variable_name]
  File "/opt/conda/lib/python3.6/site-packages/zarr/hierarchy.py", line 328, in __getitem__
    synchronizer=self._synchronizer, cache_attrs=self.attrs.cache)
  File "/opt/conda/lib/python3.6/site-packages/zarr/core.py", line 123, in __init__
    self._load_metadata()
  File "/opt/conda/lib/python3.6/site-packages/zarr/core.py", line 140, in _load_metadata
    self._load_metadata_nosync()
  File "/opt/conda/lib/python3.6/site-packages/zarr/core.py", line 149, in _load_metadata_nosync
    meta_bytes = self._store[mkey]
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/mapping.py", line 68, in __getitem__
    result = f.read()
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1280, in read
    self._fetch(self.loc, self.loc + length)
  File "<decorator-gen-156>", line 2, in _fetch
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 48, in _tracemethod
    return f(self, *args, **kwargs)
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1239, in _fetch
    self.end)
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1344, in _fetch_range
    logger.debug("Fetch: {}, {}-{}", obj_dict['name'], start, end)
Message: 'Fetch: {}, {}-{}'
Arguments: ('dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/.zarray', 0, 10485760)
1518772144.152 DEBUG gcsfs.core __exit__(args=(None, None, None), kwargs={})
1518772144.154 DEBUG gcsfs.core close(args=(), kwargs={})
1518772144.156 DEBUG gcsfs.core __del__(args=(), kwargs={})
1518772144.157 DEBUG gcsfs.core close(args=(), kwargs={})
1518772144.158 DEBUG gcsfs.core open(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/.zattrs', 'rb', None, None, None, None), kwargs={})
1518772144.159 DEBUG gcsfs.core __init__(args=(<gcsfs.core.GCSFileSystem object at 0x7f8d67f895c0>, 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/.zattrs', 'rb', 5242880, None, 'none', None), kwargs={})
1518772144.160 DEBUG gcsfs.core info(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/.zattrs',), kwargs={})
1518772144.161 DEBUG gcsfs.core _get_object(pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/.zattrs)
1518772144.162 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/',), kwargs={})
1518772144.163 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/
1518772144.164 DEBUG gcsfs.core found cached object: [{'kind': 'storage#object', 'id': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/.zattrs/1517251436316517', 'selfLink': 'https://www.googleapis.com/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Flat_bnds%2F.zattrs', 'name': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/.zattrs', 'bucket': 'pangeo-data', 'generation': '1517251436316517', 'metageneration': '1', 'timeCreated': '2018-01-29T18:43:56.291Z', 'updated': '2018-01-29T18:43:56.291Z', 'storageClass': 'REGIONAL', 'timeStorageClassUpdated': '2018-01-29T18:43:56.291Z', 'size': 194, 'md5Hash': '40KbDWFJPFFR6UHcOAvYWg==', 'mediaLink': 'https://www.googleapis.com/download/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Flat_bnds%2F.zattrs?generation=1517251436316517&alt=media', 'crc32c': 'fIihIw==', 'etag': 'COWOlofq/dgCEAE=', 'path': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/.zattrs'}]
1518772144.165 DEBUG gcsfs.core __enter__(args=(), kwargs={})
1518772144.166 DEBUG gcsfs.core _fetch(args=(0, 194), kwargs={})
--- Logging error ---
Traceback (most recent call last):
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 992, in emit
    msg = self.format(record)
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 838, in format
    return fmt.format(record)
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 575, in format
    record.message = record.getMessage()
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 338, in getMessage
    msg = msg % self.args
TypeError: not all arguments converted during string formatting
Call stack:
  File "/opt/conda/lib/python3.6/runpy.py", line 193, in _run_module_as_main
    "__main__", mod_spec)
  File "/opt/conda/lib/python3.6/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/__main__.py", line 3, in <module>
    app.launch_new_instance()
  File "/opt/conda/lib/python3.6/site-packages/traitlets/config/application.py", line 658, in launch_instance
    app.start()
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelapp.py", line 477, in start
    ioloop.IOLoop.instance().start()
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/ioloop.py", line 177, in start
    super(ZMQIOLoop, self).start()
  File "/opt/conda/lib/python3.6/site-packages/tornado/ioloop.py", line 888, in start
    handler_func(fd_obj, events)
  File "/opt/conda/lib/python3.6/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    return fn(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 440, in _handle_events
    self._handle_recv()
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 472, in _handle_recv
    self._run_callback(callback, msg)
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 414, in _run_callback
    callback(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    return fn(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 283, in dispatcher
    return self.dispatch_shell(stream, msg)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 235, in dispatch_shell
    handler(stream, idents, msg)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 399, in execute_request
    user_expressions, allow_stdin)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/ipkernel.py", line 196, in do_execute
    res = shell.run_cell(code, store_history=store_history, silent=silent)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/zmqshell.py", line 533, in run_cell
    return super(ZMQInteractiveShell, self).run_cell(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2728, in run_cell
    interactivity=interactivity, compiler=compiler, result=result)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2850, in run_ast_nodes
    if self.run_code(code, result):
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2910, in run_code
    exec(code_obj, self.user_global_ns, self.user_ns)
  File "<ipython-input-9-051a91e550af>", line 5, in <module>
    get_ipython().run_line_magic('time', 'ds = xr.open_zarr(gcsmap)')
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2095, in run_line_magic
    result = fn(*args,**kwargs)
  File "<decorator-gen-62>", line 2, in time
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/magic.py", line 187, in <lambda>
    call = lambda f, *a, **k: f(*a, **k)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/magics/execution.py", line 1238, in time
    exec(code, glob, local_ns)
  File "<timed exec>", line 1, in <module>
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 473, in open_zarr
    ds = maybe_decode_store(zarr_store)
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 461, in maybe_decode_store
    drop_variables=drop_variables)
  File "/opt/conda/lib/python3.6/site-packages/xarray/conventions.py", line 598, in decode_cf
    vars, attrs = obj.load()
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/common.py", line 133, in load
    for k, v in self.get_variables().items())
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 314, in get_variables
    for k, v in self.ds.arrays())
  File "/opt/conda/lib/python3.6/site-packages/xarray/core/utils.py", line 309, in FrozenOrderedDict
    return Frozen(OrderedDict(*args, **kwargs))
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 314, in <genexpr>
    for k, v in self.ds.arrays())
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 300, in open_store_variable
    _DIMENSION_KEY)
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 196, in _get_zarr_dims_and_attrs
    dimensions = zarr_obj.attrs[dimension_key]
  File "/opt/conda/lib/python3.6/site-packages/zarr/attrs.py", line 67, in __getitem__
    return self.asdict()[item]
  File "/opt/conda/lib/python3.6/site-packages/zarr/attrs.py", line 53, in asdict
    d = self._get_nosync()
  File "/opt/conda/lib/python3.6/site-packages/zarr/attrs.py", line 42, in _get_nosync
    data = self.store[self.key]
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/mapping.py", line 68, in __getitem__
    result = f.read()
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1280, in read
    self._fetch(self.loc, self.loc + length)
  File "<decorator-gen-156>", line 2, in _fetch
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 48, in _tracemethod
    return f(self, *args, **kwargs)
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1239, in _fetch
    self.end)
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1344, in _fetch_range
    logger.debug("Fetch: {}, {}-{}", obj_dict['name'], start, end)
Message: 'Fetch: {}, {}-{}'
Arguments: ('dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/lat_bnds/.zattrs', 0, 10485760)
1518772144.235 DEBUG gcsfs.core __exit__(args=(None, None, None), kwargs={})
1518772144.236 DEBUG gcsfs.core close(args=(), kwargs={})
1518772144.237 DEBUG gcsfs.core __del__(args=(), kwargs={})
1518772144.239 DEBUG gcsfs.core close(args=(), kwargs={})
1518772144.240 DEBUG gcsfs.core exists(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/.zarray',), kwargs={})
1518772144.241 DEBUG gcsfs.core info(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/.zarray',), kwargs={})
1518772144.242 DEBUG gcsfs.core _get_object(pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/.zarray)
1518772144.243 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/',), kwargs={})
1518772144.244 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/
1518772144.245 DEBUG gcsfs.core found cached object: [{'kind': 'storage#object', 'id': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/.zarray/1517251268949367', 'selfLink': 'https://www.googleapis.com/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Flatitude%2F.zarray', 'name': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/.zarray', 'bucket': 'pangeo-data', 'generation': '1517251268949367', 'metageneration': '1', 'timeCreated': '2018-01-29T18:41:08.933Z', 'updated': '2018-01-29T18:41:08.933Z', 'storageClass': 'REGIONAL', 'timeStorageClassUpdated': '2018-01-29T18:41:08.933Z', 'size': 318, 'md5Hash': 'O6nlTJQ+6KU0c0AUcVm46A==', 'mediaLink': 'https://www.googleapis.com/download/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Flatitude%2F.zarray?generation=1517251268949367&alt=media', 'crc32c': '3/yuGg==', 'etag': 'CPfqrrfp/dgCEAE=', 'path': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/.zarray'}]
1518772144.246 DEBUG gcsfs.core open(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/.zarray', 'rb', None, None, None, None), kwargs={})
1518772144.247 DEBUG gcsfs.core __init__(args=(<gcsfs.core.GCSFileSystem object at 0x7f8d67f895c0>, 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/.zarray', 'rb', 5242880, None, 'none', None), kwargs={})
1518772144.248 DEBUG gcsfs.core info(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/.zarray',), kwargs={})
1518772144.249 DEBUG gcsfs.core _get_object(pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/.zarray)
1518772144.250 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/',), kwargs={})
1518772144.251 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/
1518772144.252 DEBUG gcsfs.core found cached object: [{'kind': 'storage#object', 'id': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/.zarray/1517251268949367', 'selfLink': 'https://www.googleapis.com/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Flatitude%2F.zarray', 'name': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/.zarray', 'bucket': 'pangeo-data', 'generation': '1517251268949367', 'metageneration': '1', 'timeCreated': '2018-01-29T18:41:08.933Z', 'updated': '2018-01-29T18:41:08.933Z', 'storageClass': 'REGIONAL', 'timeStorageClassUpdated': '2018-01-29T18:41:08.933Z', 'size': 318, 'md5Hash': 'O6nlTJQ+6KU0c0AUcVm46A==', 'mediaLink': 'https://www.googleapis.com/download/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Flatitude%2F.zarray?generation=1517251268949367&alt=media', 'crc32c': '3/yuGg==', 'etag': 'CPfqrrfp/dgCEAE=', 'path': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/.zarray'}]
1518772144.253 DEBUG gcsfs.core __enter__(args=(), kwargs={})
1518772144.254 DEBUG gcsfs.core _fetch(args=(0, 318), kwargs={})
--- Logging error ---
Traceback (most recent call last):
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 992, in emit
    msg = self.format(record)
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 838, in format
    return fmt.format(record)
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 575, in format
    record.message = record.getMessage()
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 338, in getMessage
    msg = msg % self.args
TypeError: not all arguments converted during string formatting
Call stack:
  File "/opt/conda/lib/python3.6/runpy.py", line 193, in _run_module_as_main
    "__main__", mod_spec)
  File "/opt/conda/lib/python3.6/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/__main__.py", line 3, in <module>
    app.launch_new_instance()
  File "/opt/conda/lib/python3.6/site-packages/traitlets/config/application.py", line 658, in launch_instance
    app.start()
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelapp.py", line 477, in start
    ioloop.IOLoop.instance().start()
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/ioloop.py", line 177, in start
    super(ZMQIOLoop, self).start()
  File "/opt/conda/lib/python3.6/site-packages/tornado/ioloop.py", line 888, in start
    handler_func(fd_obj, events)
  File "/opt/conda/lib/python3.6/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    return fn(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 440, in _handle_events
    self._handle_recv()
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 472, in _handle_recv
    self._run_callback(callback, msg)
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 414, in _run_callback
    callback(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    return fn(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 283, in dispatcher
    return self.dispatch_shell(stream, msg)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 235, in dispatch_shell
    handler(stream, idents, msg)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 399, in execute_request
    user_expressions, allow_stdin)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/ipkernel.py", line 196, in do_execute
    res = shell.run_cell(code, store_history=store_history, silent=silent)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/zmqshell.py", line 533, in run_cell
    return super(ZMQInteractiveShell, self).run_cell(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2728, in run_cell
    interactivity=interactivity, compiler=compiler, result=result)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2850, in run_ast_nodes
    if self.run_code(code, result):
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2910, in run_code
    exec(code_obj, self.user_global_ns, self.user_ns)
  File "<ipython-input-9-051a91e550af>", line 5, in <module>
    get_ipython().run_line_magic('time', 'ds = xr.open_zarr(gcsmap)')
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2095, in run_line_magic
    result = fn(*args,**kwargs)
  File "<decorator-gen-62>", line 2, in time
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/magic.py", line 187, in <lambda>
    call = lambda f, *a, **k: f(*a, **k)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/magics/execution.py", line 1238, in time
    exec(code, glob, local_ns)
  File "<timed exec>", line 1, in <module>
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 473, in open_zarr
    ds = maybe_decode_store(zarr_store)
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 461, in maybe_decode_store
    drop_variables=drop_variables)
  File "/opt/conda/lib/python3.6/site-packages/xarray/conventions.py", line 598, in decode_cf
    vars, attrs = obj.load()
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/common.py", line 133, in load
    for k, v in self.get_variables().items())
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 314, in get_variables
    for k, v in self.ds.arrays())
  File "/opt/conda/lib/python3.6/site-packages/xarray/core/utils.py", line 309, in FrozenOrderedDict
    return Frozen(OrderedDict(*args, **kwargs))
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 313, in <genexpr>
    return FrozenOrderedDict((k, self.open_store_variable(k, v))
  File "/opt/conda/lib/python3.6/site-packages/zarr/hierarchy.py", line 458, in arrays
    synchronizer=self._synchronizer)
  File "/opt/conda/lib/python3.6/site-packages/zarr/core.py", line 123, in __init__
    self._load_metadata()
  File "/opt/conda/lib/python3.6/site-packages/zarr/core.py", line 140, in _load_metadata
    self._load_metadata_nosync()
  File "/opt/conda/lib/python3.6/site-packages/zarr/core.py", line 149, in _load_metadata_nosync
    meta_bytes = self._store[mkey]
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/mapping.py", line 68, in __getitem__
    result = f.read()
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1280, in read
    self._fetch(self.loc, self.loc + length)
  File "<decorator-gen-156>", line 2, in _fetch
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 48, in _tracemethod
    return f(self, *args, **kwargs)
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1239, in _fetch
    self.end)
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1344, in _fetch_range
    logger.debug("Fetch: {}, {}-{}", obj_dict['name'], start, end)
Message: 'Fetch: {}, {}-{}'
Arguments: ('dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/.zarray', 0, 10485760)
1518772144.338 DEBUG gcsfs.core __exit__(args=(None, None, None), kwargs={})
1518772144.339 DEBUG gcsfs.core close(args=(), kwargs={})
1518772144.340 DEBUG gcsfs.core __del__(args=(), kwargs={})
1518772144.341 DEBUG gcsfs.core close(args=(), kwargs={})
1518772144.343 DEBUG gcsfs.core exists(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/.zarray',), kwargs={})
1518772144.344 DEBUG gcsfs.core info(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/.zarray',), kwargs={})
1518772144.345 DEBUG gcsfs.core _get_object(pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/.zarray)
1518772144.346 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/',), kwargs={})
1518772144.348 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/
1518772144.351 DEBUG gcsfs.core found cached object: [{'kind': 'storage#object', 'id': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/.zarray/1517251268949367', 'selfLink': 'https://www.googleapis.com/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Flatitude%2F.zarray', 'name': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/.zarray', 'bucket': 'pangeo-data', 'generation': '1517251268949367', 'metageneration': '1', 'timeCreated': '2018-01-29T18:41:08.933Z', 'updated': '2018-01-29T18:41:08.933Z', 'storageClass': 'REGIONAL', 'timeStorageClassUpdated': '2018-01-29T18:41:08.933Z', 'size': 318, 'md5Hash': 'O6nlTJQ+6KU0c0AUcVm46A==', 'mediaLink': 'https://www.googleapis.com/download/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Flatitude%2F.zarray?generation=1517251268949367&alt=media', 'crc32c': '3/yuGg==', 'etag': 'CPfqrrfp/dgCEAE=', 'path': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/.zarray'}]
1518772144.352 DEBUG gcsfs.core open(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/.zarray', 'rb', None, None, None, None), kwargs={})
1518772144.353 DEBUG gcsfs.core __init__(args=(<gcsfs.core.GCSFileSystem object at 0x7f8d67f895c0>, 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/.zarray', 'rb', 5242880, None, 'none', None), kwargs={})
1518772144.356 DEBUG gcsfs.core info(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/.zarray',), kwargs={})
1518772144.357 DEBUG gcsfs.core _get_object(pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/.zarray)
1518772144.359 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/',), kwargs={})
1518772144.360 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/
1518772144.361 DEBUG gcsfs.core found cached object: [{'kind': 'storage#object', 'id': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/.zarray/1517251268949367', 'selfLink': 'https://www.googleapis.com/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Flatitude%2F.zarray', 'name': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/.zarray', 'bucket': 'pangeo-data', 'generation': '1517251268949367', 'metageneration': '1', 'timeCreated': '2018-01-29T18:41:08.933Z', 'updated': '2018-01-29T18:41:08.933Z', 'storageClass': 'REGIONAL', 'timeStorageClassUpdated': '2018-01-29T18:41:08.933Z', 'size': 318, 'md5Hash': 'O6nlTJQ+6KU0c0AUcVm46A==', 'mediaLink': 'https://www.googleapis.com/download/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Flatitude%2F.zarray?generation=1517251268949367&alt=media', 'crc32c': '3/yuGg==', 'etag': 'CPfqrrfp/dgCEAE=', 'path': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/.zarray'}]
1518772144.362 DEBUG gcsfs.core __enter__(args=(), kwargs={})
1518772144.363 DEBUG gcsfs.core _fetch(args=(0, 318), kwargs={})
--- Logging error ---
Traceback (most recent call last):
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 992, in emit
    msg = self.format(record)
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 838, in format
    return fmt.format(record)
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 575, in format
    record.message = record.getMessage()
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 338, in getMessage
    msg = msg % self.args
TypeError: not all arguments converted during string formatting
Call stack:
  File "/opt/conda/lib/python3.6/runpy.py", line 193, in _run_module_as_main
    "__main__", mod_spec)
  File "/opt/conda/lib/python3.6/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/__main__.py", line 3, in <module>
    app.launch_new_instance()
  File "/opt/conda/lib/python3.6/site-packages/traitlets/config/application.py", line 658, in launch_instance
    app.start()
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelapp.py", line 477, in start
    ioloop.IOLoop.instance().start()
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/ioloop.py", line 177, in start
    super(ZMQIOLoop, self).start()
  File "/opt/conda/lib/python3.6/site-packages/tornado/ioloop.py", line 888, in start
    handler_func(fd_obj, events)
  File "/opt/conda/lib/python3.6/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    return fn(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 440, in _handle_events
    self._handle_recv()
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 472, in _handle_recv
    self._run_callback(callback, msg)
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 414, in _run_callback
    callback(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    return fn(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 283, in dispatcher
    return self.dispatch_shell(stream, msg)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 235, in dispatch_shell
    handler(stream, idents, msg)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 399, in execute_request
    user_expressions, allow_stdin)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/ipkernel.py", line 196, in do_execute
    res = shell.run_cell(code, store_history=store_history, silent=silent)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/zmqshell.py", line 533, in run_cell
    return super(ZMQInteractiveShell, self).run_cell(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2728, in run_cell
    interactivity=interactivity, compiler=compiler, result=result)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2850, in run_ast_nodes
    if self.run_code(code, result):
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2910, in run_code
    exec(code_obj, self.user_global_ns, self.user_ns)
  File "<ipython-input-9-051a91e550af>", line 5, in <module>
    get_ipython().run_line_magic('time', 'ds = xr.open_zarr(gcsmap)')
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2095, in run_line_magic
    result = fn(*args,**kwargs)
  File "<decorator-gen-62>", line 2, in time
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/magic.py", line 187, in <lambda>
    call = lambda f, *a, **k: f(*a, **k)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/magics/execution.py", line 1238, in time
    exec(code, glob, local_ns)
  File "<timed exec>", line 1, in <module>
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 473, in open_zarr
    ds = maybe_decode_store(zarr_store)
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 461, in maybe_decode_store
    drop_variables=drop_variables)
  File "/opt/conda/lib/python3.6/site-packages/xarray/conventions.py", line 598, in decode_cf
    vars, attrs = obj.load()
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/common.py", line 133, in load
    for k, v in self.get_variables().items())
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 314, in get_variables
    for k, v in self.ds.arrays())
  File "/opt/conda/lib/python3.6/site-packages/xarray/core/utils.py", line 309, in FrozenOrderedDict
    return Frozen(OrderedDict(*args, **kwargs))
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 314, in <genexpr>
    for k, v in self.ds.arrays())
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 298, in open_store_variable
    data = indexing.LazilyIndexedArray(ZarrArrayWrapper(name, self))
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 76, in __init__
    array = self.get_array()
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 83, in get_array
    return self.datastore.ds[self.variable_name]
  File "/opt/conda/lib/python3.6/site-packages/zarr/hierarchy.py", line 328, in __getitem__
    synchronizer=self._synchronizer, cache_attrs=self.attrs.cache)
  File "/opt/conda/lib/python3.6/site-packages/zarr/core.py", line 123, in __init__
    self._load_metadata()
  File "/opt/conda/lib/python3.6/site-packages/zarr/core.py", line 140, in _load_metadata
    self._load_metadata_nosync()
  File "/opt/conda/lib/python3.6/site-packages/zarr/core.py", line 149, in _load_metadata_nosync
    meta_bytes = self._store[mkey]
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/mapping.py", line 68, in __getitem__
    result = f.read()
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1280, in read
    self._fetch(self.loc, self.loc + length)
  File "<decorator-gen-156>", line 2, in _fetch
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 48, in _tracemethod
    return f(self, *args, **kwargs)
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1239, in _fetch
    self.end)
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1344, in _fetch_range
    logger.debug("Fetch: {}, {}-{}", obj_dict['name'], start, end)
Message: 'Fetch: {}, {}-{}'
Arguments: ('dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/.zarray', 0, 10485760)
1518772144.455 DEBUG gcsfs.core __exit__(args=(None, None, None), kwargs={})
1518772144.457 DEBUG gcsfs.core close(args=(), kwargs={})
1518772144.458 DEBUG gcsfs.core __del__(args=(), kwargs={})
1518772144.459 DEBUG gcsfs.core close(args=(), kwargs={})
1518772144.460 DEBUG gcsfs.core open(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/.zattrs', 'rb', None, None, None, None), kwargs={})
1518772144.461 DEBUG gcsfs.core __init__(args=(<gcsfs.core.GCSFileSystem object at 0x7f8d67f895c0>, 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/.zattrs', 'rb', 5242880, None, 'none', None), kwargs={})
1518772144.462 DEBUG gcsfs.core info(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/.zattrs',), kwargs={})
1518772144.463 DEBUG gcsfs.core _get_object(pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/.zattrs)
1518772144.464 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/',), kwargs={})
1518772144.464 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/
1518772144.465 DEBUG gcsfs.core found cached object: [{'kind': 'storage#object', 'id': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/.zattrs/1517251269580330', 'selfLink': 'https://www.googleapis.com/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Flatitude%2F.zattrs', 'name': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/.zattrs', 'bucket': 'pangeo-data', 'generation': '1517251269580330', 'metageneration': '1', 'timeCreated': '2018-01-29T18:41:09.559Z', 'updated': '2018-01-29T18:41:09.559Z', 'storageClass': 'REGIONAL', 'timeStorageClassUpdated': '2018-01-29T18:41:09.559Z', 'size': 241, 'md5Hash': 'I+Fp+UHsHf8WW5xfU/J0ug==', 'mediaLink': 'https://www.googleapis.com/download/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Flatitude%2F.zattrs?generation=1517251269580330&alt=media', 'crc32c': 'hn3VYg==', 'etag': 'CKqs1bfp/dgCEAE=', 'path': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/.zattrs'}]
1518772144.466 DEBUG gcsfs.core __enter__(args=(), kwargs={})
1518772144.467 DEBUG gcsfs.core _fetch(args=(0, 241), kwargs={})
--- Logging error ---
Traceback (most recent call last):
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 992, in emit
    msg = self.format(record)
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 838, in format
    return fmt.format(record)
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 575, in format
    record.message = record.getMessage()
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 338, in getMessage
    msg = msg % self.args
TypeError: not all arguments converted during string formatting
Call stack:
  File "/opt/conda/lib/python3.6/runpy.py", line 193, in _run_module_as_main
    "__main__", mod_spec)
  File "/opt/conda/lib/python3.6/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/__main__.py", line 3, in <module>
    app.launch_new_instance()
  File "/opt/conda/lib/python3.6/site-packages/traitlets/config/application.py", line 658, in launch_instance
    app.start()
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelapp.py", line 477, in start
    ioloop.IOLoop.instance().start()
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/ioloop.py", line 177, in start
    super(ZMQIOLoop, self).start()
  File "/opt/conda/lib/python3.6/site-packages/tornado/ioloop.py", line 888, in start
    handler_func(fd_obj, events)
  File "/opt/conda/lib/python3.6/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    return fn(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 440, in _handle_events
    self._handle_recv()
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 472, in _handle_recv
    self._run_callback(callback, msg)
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 414, in _run_callback
    callback(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    return fn(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 283, in dispatcher
    return self.dispatch_shell(stream, msg)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 235, in dispatch_shell
    handler(stream, idents, msg)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 399, in execute_request
    user_expressions, allow_stdin)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/ipkernel.py", line 196, in do_execute
    res = shell.run_cell(code, store_history=store_history, silent=silent)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/zmqshell.py", line 533, in run_cell
    return super(ZMQInteractiveShell, self).run_cell(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2728, in run_cell
    interactivity=interactivity, compiler=compiler, result=result)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2850, in run_ast_nodes
    if self.run_code(code, result):
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2910, in run_code
    exec(code_obj, self.user_global_ns, self.user_ns)
  File "<ipython-input-9-051a91e550af>", line 5, in <module>
    get_ipython().run_line_magic('time', 'ds = xr.open_zarr(gcsmap)')
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2095, in run_line_magic
    result = fn(*args,**kwargs)
  File "<decorator-gen-62>", line 2, in time
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/magic.py", line 187, in <lambda>
    call = lambda f, *a, **k: f(*a, **k)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/magics/execution.py", line 1238, in time
    exec(code, glob, local_ns)
  File "<timed exec>", line 1, in <module>
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 473, in open_zarr
    ds = maybe_decode_store(zarr_store)
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 461, in maybe_decode_store
    drop_variables=drop_variables)
  File "/opt/conda/lib/python3.6/site-packages/xarray/conventions.py", line 598, in decode_cf
    vars, attrs = obj.load()
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/common.py", line 133, in load
    for k, v in self.get_variables().items())
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 314, in get_variables
    for k, v in self.ds.arrays())
  File "/opt/conda/lib/python3.6/site-packages/xarray/core/utils.py", line 309, in FrozenOrderedDict
    return Frozen(OrderedDict(*args, **kwargs))
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 314, in <genexpr>
    for k, v in self.ds.arrays())
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 300, in open_store_variable
    _DIMENSION_KEY)
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 196, in _get_zarr_dims_and_attrs
    dimensions = zarr_obj.attrs[dimension_key]
  File "/opt/conda/lib/python3.6/site-packages/zarr/attrs.py", line 67, in __getitem__
    return self.asdict()[item]
  File "/opt/conda/lib/python3.6/site-packages/zarr/attrs.py", line 53, in asdict
    d = self._get_nosync()
  File "/opt/conda/lib/python3.6/site-packages/zarr/attrs.py", line 42, in _get_nosync
    data = self.store[self.key]
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/mapping.py", line 68, in __getitem__
    result = f.read()
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1280, in read
    self._fetch(self.loc, self.loc + length)
  File "<decorator-gen-156>", line 2, in _fetch
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 48, in _tracemethod
    return f(self, *args, **kwargs)
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1239, in _fetch
    self.end)
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1344, in _fetch_range
    logger.debug("Fetch: {}, {}-{}", obj_dict['name'], start, end)
Message: 'Fetch: {}, {}-{}'
Arguments: ('dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/latitude/.zattrs', 0, 10485760)

@rabernat
Copy link
Member

When I call .persist(), I get this on the client

1518772540.631 DEBUG gcsfs.core Serialize with state: {'project': 'pangeo-181919', 'access': 'full_control', 'scope': 'https://www.googleapis.com/auth/devstorage.full_control', 'consistency': 'none', 'token': None, 'session': <google.auth.transport.requests.AuthorizedSession object at 0x7f8db1e527b8>, 'method': 'google_default', 'cache_timeout': 60, '_listing_cache': {}}

I tried using client.run to turn on logging on the workers, but I do not know how to obtain the logs from the workers.

@rabernat
Copy link
Member

When I actually load persisted data, I get these log messages

1518772804.297 DEBUG gcsfs.core exists(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray',), kwargs={})
1518772804.298 DEBUG gcsfs.core info(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray',), kwargs={})
1518772804.299 DEBUG gcsfs.core _get_object(pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray)
1518772804.300 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/',), kwargs={})
1518772804.301 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/
1518772804.302 DEBUG gcsfs.core expired cache path: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/ retrieved_time: 1518772655.936 cache_age: 148.367 cache_timeout: 60.000
1518772804.303 DEBUG gcsfs.core _call(get, b/{}/o/{}, args=('pangeo-data', 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray'), kwargs={})
1518772804.345 DEBUG gcsfs.core _get_object result: {'kind': 'storage#object', 'id': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray/1517251342171118', 'selfLink': 'https://www.googleapis.com/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Fcrs%2F.zarray', 'name': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray', 'bucket': 'pangeo-data', 'generation': '1517251342171118', 'metageneration': '1', 'timeCreated': '2018-01-29T18:42:22.133Z', 'updated': '2018-01-29T18:42:22.133Z', 'storageClass': 'REGIONAL', 'timeStorageClassUpdated': '2018-01-29T18:42:22.133Z', 'size': 166, 'md5Hash': '9CsCC+aV78cxg9+tOOvROw==', 'mediaLink': 'https://www.googleapis.com/download/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Fcrs%2F.zarray?generation=1517251342171118&alt=media', 'crc32c': 'oDZIWA==', 'etag': 'CO73o9rp/dgCEAE=', 'path': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray'}
1518772804.347 DEBUG gcsfs.core open(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray', 'rb', None, None, None, None), kwargs={})
1518772804.348 DEBUG gcsfs.core __init__(args=(<gcsfs.core.GCSFileSystem object at 0x7fd0a5beb0b8>, 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray', 'rb', 5242880, None, 'none', None), kwargs={})
1518772804.349 DEBUG gcsfs.core info(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray',), kwargs={})
1518772804.350 DEBUG gcsfs.core _get_object(pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray)
1518772804.351 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/',), kwargs={})
1518772804.352 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/
1518772804.353 DEBUG gcsfs.core _call(get, b/{}/o/{}, args=('pangeo-data', 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray'), kwargs={})
1518772804.377 DEBUG gcsfs.core _get_object result: {'kind': 'storage#object', 'id': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray/1517251342171118', 'selfLink': 'https://www.googleapis.com/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Fcrs%2F.zarray', 'name': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray', 'bucket': 'pangeo-data', 'generation': '1517251342171118', 'metageneration': '1', 'timeCreated': '2018-01-29T18:42:22.133Z', 'updated': '2018-01-29T18:42:22.133Z', 'storageClass': 'REGIONAL', 'timeStorageClassUpdated': '2018-01-29T18:42:22.133Z', 'size': 166, 'md5Hash': '9CsCC+aV78cxg9+tOOvROw==', 'mediaLink': 'https://www.googleapis.com/download/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Fcrs%2F.zarray?generation=1517251342171118&alt=media', 'crc32c': 'oDZIWA==', 'etag': 'CO73o9rp/dgCEAE=', 'path': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray'}
1518772804.379 DEBUG gcsfs.core __enter__(args=(), kwargs={})
1518772804.381 DEBUG gcsfs.core _fetch(args=(0, 166), kwargs={})
--- Logging error ---
Traceback (most recent call last):
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 992, in emit
    msg = self.format(record)
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 838, in format
    return fmt.format(record)
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 575, in format
    record.message = record.getMessage()
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 338, in getMessage
    msg = msg % self.args
TypeError: not all arguments converted during string formatting
Call stack:
  File "/opt/conda/lib/python3.6/runpy.py", line 193, in _run_module_as_main
    "__main__", mod_spec)
  File "/opt/conda/lib/python3.6/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/__main__.py", line 3, in <module>
    app.launch_new_instance()
  File "/opt/conda/lib/python3.6/site-packages/traitlets/config/application.py", line 658, in launch_instance
    app.start()
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelapp.py", line 477, in start
    ioloop.IOLoop.instance().start()
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/ioloop.py", line 177, in start
    super(ZMQIOLoop, self).start()
  File "/opt/conda/lib/python3.6/site-packages/tornado/ioloop.py", line 888, in start
    handler_func(fd_obj, events)
  File "/opt/conda/lib/python3.6/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    return fn(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 440, in _handle_events
    self._handle_recv()
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 472, in _handle_recv
    self._run_callback(callback, msg)
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 414, in _run_callback
    callback(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    return fn(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 283, in dispatcher
    return self.dispatch_shell(stream, msg)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 235, in dispatch_shell
    handler(stream, idents, msg)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 399, in execute_request
    user_expressions, allow_stdin)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/ipkernel.py", line 196, in do_execute
    res = shell.run_cell(code, store_history=store_history, silent=silent)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/zmqshell.py", line 533, in run_cell
    return super(ZMQInteractiveShell, self).run_cell(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2728, in run_cell
    interactivity=interactivity, compiler=compiler, result=result)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2856, in run_ast_nodes
    if self.run_code(code, result):
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2910, in run_code
    exec(code_obj, self.user_global_ns, self.user_ns)
  File "<ipython-input-11-24123d9b1f52>", line 1, in <module>
    sla_timeseries.plot()
  File "/opt/conda/lib/python3.6/site-packages/xarray/plot/plot.py", line 318, in __call__
    return plot(self._da, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/xarray/plot/plot.py", line 150, in plot
    return plotfunc(darray, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/xarray/plot/plot.py", line 226, in line
    ax.set_title(darray._title_for_slice())
  File "/opt/conda/lib/python3.6/site-packages/xarray/core/dataarray.py", line 1812, in _title_for_slice
    dim=dim, v=format_item(coord.values)))
  File "/opt/conda/lib/python3.6/site-packages/xarray/core/dataarray.py", line 411, in values
    return self.variable.values
  File "/opt/conda/lib/python3.6/site-packages/xarray/core/variable.py", line 392, in values
    return _as_array_or_item(self._data)
  File "/opt/conda/lib/python3.6/site-packages/xarray/core/variable.py", line 216, in _as_array_or_item
    data = np.asarray(data)
  File "/opt/conda/lib/python3.6/site-packages/numpy/core/numeric.py", line 492, in asarray
    return array(a, dtype, copy=False, order=order)
  File "/opt/conda/lib/python3.6/site-packages/xarray/core/indexing.py", line 520, in __array__
    return np.asarray(array[self.key], dtype=None)
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 86, in __getitem__
    array = self.get_array()
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 83, in get_array
    return self.datastore.ds[self.variable_name]
  File "/opt/conda/lib/python3.6/site-packages/zarr/hierarchy.py", line 328, in __getitem__
    synchronizer=self._synchronizer, cache_attrs=self.attrs.cache)
  File "/opt/conda/lib/python3.6/site-packages/zarr/core.py", line 123, in __init__
    self._load_metadata()
  File "/opt/conda/lib/python3.6/site-packages/zarr/core.py", line 140, in _load_metadata
    self._load_metadata_nosync()
  File "/opt/conda/lib/python3.6/site-packages/zarr/core.py", line 149, in _load_metadata_nosync
    meta_bytes = self._store[mkey]
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/mapping.py", line 68, in __getitem__
    result = f.read()
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1280, in read
    self._fetch(self.loc, self.loc + length)
  File "<decorator-gen-156>", line 2, in _fetch
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 48, in _tracemethod
    return f(self, *args, **kwargs)
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1239, in _fetch
    self.end)
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1344, in _fetch_range
    logger.debug("Fetch: {}, {}-{}", obj_dict['name'], start, end)
Message: 'Fetch: {}, {}-{}'
Arguments: ('dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/.zarray', 0, 10485760)
1518772804.449 DEBUG gcsfs.core __exit__(args=(None, None, None), kwargs={})
1518772804.450 DEBUG gcsfs.core close(args=(), kwargs={})
1518772804.452 DEBUG gcsfs.core __del__(args=(), kwargs={})
1518772804.453 DEBUG gcsfs.core close(args=(), kwargs={})
1518772804.454 DEBUG gcsfs.core open(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/0', 'rb', None, None, None, None), kwargs={})
1518772804.455 DEBUG gcsfs.core __init__(args=(<gcsfs.core.GCSFileSystem object at 0x7fd0a5beb0b8>, 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/0', 'rb', 5242880, None, 'none', None), kwargs={})
1518772804.456 DEBUG gcsfs.core info(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/0',), kwargs={})
1518772804.456 DEBUG gcsfs.core _get_object(pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/0)
1518772804.457 DEBUG gcsfs.core _maybe_get_cached_listing(args=('pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/',), kwargs={})
1518772804.458 DEBUG gcsfs.core _maybe_get_cached_listing: pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/
1518772804.459 DEBUG gcsfs.core _call(get, b/{}/o/{}, args=('pangeo-data', 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/0'), kwargs={})
1518772804.485 DEBUG gcsfs.core _get_object result: {'kind': 'storage#object', 'id': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/0/1517251365067403', 'selfLink': 'https://www.googleapis.com/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Fcrs%2F0', 'name': 'dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/0', 'bucket': 'pangeo-data', 'generation': '1517251365067403', 'metageneration': '1', 'timeCreated': '2018-01-29T18:42:45.044Z', 'updated': '2018-01-29T18:42:45.044Z', 'storageClass': 'REGIONAL', 'timeStorageClassUpdated': '2018-01-29T18:42:45.044Z', 'size': 4, 'md5Hash': 'yO0gwjupH0V3+EyUDIbH2w==', 'mediaLink': 'https://www.googleapis.com/download/storage/v1/b/pangeo-data/o/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt%2Fcrs%2F0?generation=1517251365067403&alt=media', 'crc32c': 'F9TaBw==', 'etag': 'CIu1meXp/dgCEAE=', 'path': 'pangeo-data/dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/0'}
1518772804.487 DEBUG gcsfs.core __enter__(args=(), kwargs={})
1518772804.488 DEBUG gcsfs.core _fetch(args=(0, 4), kwargs={})
--- Logging error ---
Traceback (most recent call last):
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 992, in emit
    msg = self.format(record)
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 838, in format
    return fmt.format(record)
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 575, in format
    record.message = record.getMessage()
  File "/opt/conda/lib/python3.6/logging/__init__.py", line 338, in getMessage
    msg = msg % self.args
TypeError: not all arguments converted during string formatting
Call stack:
  File "/opt/conda/lib/python3.6/runpy.py", line 193, in _run_module_as_main
    "__main__", mod_spec)
  File "/opt/conda/lib/python3.6/runpy.py", line 85, in _run_code
    exec(code, run_globals)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/__main__.py", line 3, in <module>
    app.launch_new_instance()
  File "/opt/conda/lib/python3.6/site-packages/traitlets/config/application.py", line 658, in launch_instance
    app.start()
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelapp.py", line 477, in start
    ioloop.IOLoop.instance().start()
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/ioloop.py", line 177, in start
    super(ZMQIOLoop, self).start()
  File "/opt/conda/lib/python3.6/site-packages/tornado/ioloop.py", line 888, in start
    handler_func(fd_obj, events)
  File "/opt/conda/lib/python3.6/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    return fn(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 440, in _handle_events
    self._handle_recv()
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 472, in _handle_recv
    self._run_callback(callback, msg)
  File "/opt/conda/lib/python3.6/site-packages/zmq/eventloop/zmqstream.py", line 414, in _run_callback
    callback(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/tornado/stack_context.py", line 277, in null_wrapper
    return fn(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 283, in dispatcher
    return self.dispatch_shell(stream, msg)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 235, in dispatch_shell
    handler(stream, idents, msg)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/kernelbase.py", line 399, in execute_request
    user_expressions, allow_stdin)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/ipkernel.py", line 196, in do_execute
    res = shell.run_cell(code, store_history=store_history, silent=silent)
  File "/opt/conda/lib/python3.6/site-packages/ipykernel/zmqshell.py", line 533, in run_cell
    return super(ZMQInteractiveShell, self).run_cell(*args, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2728, in run_cell
    interactivity=interactivity, compiler=compiler, result=result)
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2856, in run_ast_nodes
    if self.run_code(code, result):
  File "/opt/conda/lib/python3.6/site-packages/IPython/core/interactiveshell.py", line 2910, in run_code
    exec(code_obj, self.user_global_ns, self.user_ns)
  File "<ipython-input-11-24123d9b1f52>", line 1, in <module>
    sla_timeseries.plot()
  File "/opt/conda/lib/python3.6/site-packages/xarray/plot/plot.py", line 318, in __call__
    return plot(self._da, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/xarray/plot/plot.py", line 150, in plot
    return plotfunc(darray, **kwargs)
  File "/opt/conda/lib/python3.6/site-packages/xarray/plot/plot.py", line 226, in line
    ax.set_title(darray._title_for_slice())
  File "/opt/conda/lib/python3.6/site-packages/xarray/core/dataarray.py", line 1812, in _title_for_slice
    dim=dim, v=format_item(coord.values)))
  File "/opt/conda/lib/python3.6/site-packages/xarray/core/dataarray.py", line 411, in values
    return self.variable.values
  File "/opt/conda/lib/python3.6/site-packages/xarray/core/variable.py", line 392, in values
    return _as_array_or_item(self._data)
  File "/opt/conda/lib/python3.6/site-packages/xarray/core/variable.py", line 216, in _as_array_or_item
    data = np.asarray(data)
  File "/opt/conda/lib/python3.6/site-packages/numpy/core/numeric.py", line 492, in asarray
    return array(a, dtype, copy=False, order=order)
  File "/opt/conda/lib/python3.6/site-packages/xarray/core/indexing.py", line 520, in __array__
    return np.asarray(array[self.key], dtype=None)
  File "/opt/conda/lib/python3.6/site-packages/xarray/backends/zarr.py", line 88, in __getitem__
    return array[key.tuple]
  File "/opt/conda/lib/python3.6/site-packages/zarr/core.py", line 559, in __getitem__
    return self.get_basic_selection(selection, fields=fields)
  File "/opt/conda/lib/python3.6/site-packages/zarr/core.py", line 682, in get_basic_selection
    fields=fields)
  File "/opt/conda/lib/python3.6/site-packages/zarr/core.py", line 698, in _get_basic_selection_zd
    cdata = self.chunk_store[ckey]
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/mapping.py", line 68, in __getitem__
    result = f.read()
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1280, in read
    self._fetch(self.loc, self.loc + length)
  File "<decorator-gen-156>", line 2, in _fetch
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 48, in _tracemethod
    return f(self, *args, **kwargs)
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1239, in _fetch
    self.end)
  File "/home/jovyan/.local/lib/python3.6/site-packages/gcsfs/core.py", line 1344, in _fetch_range
    logger.debug("Fetch: {}, {}-{}", obj_dict['name'], start, end)
Message: 'Fetch: {}, {}-{}'
Arguments: ('dataset-duacs-rep-global-merged-allsat-phy-l4-v3-alt/crs/0', 0, 10485760)
1518772804.587 DEBUG gcsfs.core __exit__(args=(None, None, None), kwargs={})
1518772804.588 DEBUG gcsfs.core close(args=(), kwargs={})
1518772804.590 DEBUG gcsfs.core __del__(args=(), kwargs={})
1518772804.592 DEBUG gcsfs.core close(args=(), kwargs={})

@mrocklin
Copy link
Member Author

Do you have a reasonably easy repro case of this slowdown? Would it be possible for to run one with the gcsfs.core and gcsfs.gcsfuse loggers at the logging.DEBUG level? That will produce a lot of tracing, but could be useful to track down where this perf issue is coming from.

See #112 (comment)

@martindurant
Copy link
Contributor

  1. obviously that logging error is annoying and should be fixed (was on my branch)
  2. the directory cache expires far to fast. I would suggest 3600s (or not at all!). When it expires, we seem to fall back to calling HEAD every time for every file.
  3. exists/info on a file that does not exist also results in a HEAD, even if we've previously cached the parent directory's file listing, and we know there is no such file.
  4. apparently the zarr code is calling exists() and then open(); if caching were working, this would not matter, but as it is, we are calling HEAD twice (may be better to call open() with try/except).

@asford
Copy link

asford commented Feb 16, 2018

Agreed that zarr should call through open/except, but the access pattern does make sense. Should be supported in a reasonable way in the cache.

Also noticed the logging issue and fixed it in fsspec/gcsfs#73.

@rabernat
Copy link
Member

Question: if I ! pip installed something from within my notebook, how persistent is this installation? Do I need to do it again every time my server restarts?

@martindurant
Copy link
Contributor

Question: if I ! pip installed something from within my notebook, how persistent is this installation? Do I need to do it again every time my server restarts?

This will persist, it actually writes into your site-packages folder within wherever python is installed; this can sometimes cause a problem when installing from conda and pip and setup.py, although in theory they should just clobber one-another.

@asford
Copy link

asford commented Feb 16, 2018

fsspec/gcsfs#57 has been updated with fixes for @martindurant's feedback above.

@rabernat
Copy link
Member

I tried your latest branch and unfortunately it did not change the performance.

But i am still not 100% convinced that I am correctly propagating the extra pip packages to the workers. I don't know if / how I need to specify the --upgrade flag.

@asford
Copy link

asford commented Feb 16, 2018

I'm assuming your build is a pretty recent version of dask docker. In that case it has not installed the updated image. See prepare.sh. This is just a shot in the dark, but can you try:

cluster = KubeCluster(n_workers=20, 
                      env={'EXTRA_PIP_PACKAGES': '--upgrade git+https://github.com/asford/gcsfs.git@per_dir_cache'})
client = Client(cluster)

@rabernat
Copy link
Member

Adding --upgrade to EXTRA_PIP_PACKAGES makes everything work beautifully. No more long spinup time. Hooray! 🥇

@asford
Copy link

asford commented Feb 19, 2018

👏 We're planning on merging that pull into gcsfs@master shortly. I'm not tracking this this repo, so would you all mind cross-posting onto gcsfs and referencing your threads here for any issues that come up with feature?

@rabernat
Copy link
Member

rabernat commented Feb 20, 2018

Now that fsspec/gcsfs#57 has been merged, I guess we are just waiting for a dask gcsfs release before marking this closed?

@mrocklin
Copy link
Member Author

mrocklin commented Feb 20, 2018 via email

@rabernat
Copy link
Member

Sorry it's gcsfs. Corrected above.

@martindurant
Copy link
Contributor

There will be no need to change dask here.

gcsfs can be released if that is useful, but I don't think all of #112 (comment) have been met yet. The merger means that you can now pip install from the repo without specifying a branch.

@rabernat
Copy link
Member

@martindurant: thanks for the clarification. I will consider this resolved when the fix has been propagated to the default pangeo.pydata.org environment (rather than using the EXTRA_PIP_PACKAGES workaround). Unfortunately my technical understanding of how that default environment is specified is very limited. Is it in the dask helm chart? This repo's dask worker DOCKERFILE? Do we have to restart the whole Kubernetes cluster to propagate such a change? I'm in over my head in terms of cloud deployment but trying to catch up!

@rabernat
Copy link
Member

Closed by #128

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

5 participants