parse error: Malformed object: missing object end line

Running v0.2.4.7-alpha-dev (git-17c24b3118224d65) I got

Jan 02 05:16:34.000 [warn] parse error: Malformed object: missing object end line
Jan 02 05:16:34.000 [warn] Unparseable microdescriptor

My debug-level logs are only slightly more helpful:

...
Jan 02 05:16:34.000 [debug] conn_read_callback(): socket -1 wants to read.
Jan 02 05:16:34.000 [debug] fetch_from_buf_http(): headerlen 197, bodylen 9763.
Jan 02 05:16:34.000 [debug] connection_dir_client_reached_eof(): Received response from directory server '94.254.1.254:443': 200 "OK" (purpose: 19)
Jan 02 05:16:34.000 [debug] router_new_address_suggestion(): Got X-Your-Address-Is: 87.213.50.130.
Jan 02 05:16:34.000 [debug] connection_dir_client_reached_eof(): Time on received directory is within tolerance; we are -88 seconds skewed.  (That's okay.)
Jan 02 05:16:34.000 [info] connection_dir_client_reached_eof(): Received answer to microdescriptor request (status 200, size 16655) from server '94.254.1.254:443'
Jan 02 05:16:34.000 [warn] parse error: Malformed object: missing object end line
Jan 02 05:16:34.000 [warn] Unparseable microdescriptor
Jan 02 05:16:34.000 [debug] download_status_increment_failure(): r9clvX7cTGes/a70f5pyLkOy6QUOMHMN0hu/0D3mRdw failed 1 time(s); I'll try again immediately.
Jan 02 05:16:34.000 [debug] download_status_increment_failure(): r9gxpWtpN+lvdC+azIzBRV8bKEClpqVOWlb0DMcFfHs failed 1 time(s); I'll try again immediately.
Jan 02 05:16:34.000 [debug] download_status_increment_failure(): r+WKD+7TLtTYCS0P74etXSv+LTQT0KdX3MlIeV9T8r0 failed 1 time(s); I'll try again immediately.
...

http://94.254.1.254/ seems to be timing out now, so it's likely this is a problem with the particular dir mirror I picked. But in any case the warn messages should either be more helpful or more quiet.

changed milestone to %Tor: 0.2.4.x-final

added component::core tor/tor milestone::Tor: 0.2.4.x-final priority::low resolution::duplicate status::closed tor-client type::defect version::tor 0.2.4.7-alpha labels

Hm. That was on download, or on reading from cache?

I believe it was on download.

I have the same warning when reading from cache on restart. The offending tokens are below.

@last-listed 2013-01-15 07:13:33
onion-key
-----BEGIN RSA PUBLIC KEY-----
MIGJAoGBANlz9VTPccBpq5TlVnbxKkUsfakecHe1/9i6s1OPBYtILBuUTc0o5FIr
SWCDbgFbSW5D8liINcxXwvTS8H8pXZmhndNL3ZjLAulN4SbPAlm8JeepMb2BMlxw
WtyzGrTEIiol2wnYJSGTNuTMtqTNY3O/YLCC0ldoyNZQEsOA5C1bAgMBAAE=
-----END RSA PUBLIC KEY-----
@last-listed 2013-01-15 07:13:33
onion-key
-----BEGIN RSA PUBLIC KEY-----
MIGJAoGBAKHkrgqf576iQMzOIzmS0Z+rjTh2Q3v936L3zqawNcuSXcy7RKPbdgiK
b8nmS4xm57buohWKXR25@last-listed 2013-01-15 08:32:48
onion-key
-----BEGIN RSA PUBLIC KEY-----
MIGJAoGBAOQOfl+1nX5mPrwbTDeGSnxJQwW8dGdb405+/chDkMxOGJ4HJo4mcGP2
6GNbR4JEEIyMrE7msNe1Ccgg2nII3wM0dbMjiABOOYLn11ArEw7wDMoMQGmrBAH0
X7Eg8eUxx1gPsE9wpD27eVjYN9KNjqsbvLGFAXQfnKNsCM6neQ7HAgMBAAE=
-----END RSA PUBLIC KEY-----

and

@last-listed 2013-01-15 11:31:47
onion-key
-----BEGIN RSA PUBLIC KEY-----
MIGJAoGBAMpjsCEz4sRS7VQIDElsKFxqdkhP4gjMnFicgBZGl8jN3t1skWzi6C2B
A8laUj03bvHUEo9e4mW2cW@last-listed 2013-01-15 13:11:13
onion-key
-----BEGIN RSA PUBLIC KEY-----
MIGJAoGBAKnI/S/EA5uOXqOJfdUosD74i6mtcNNvUYIjCMnLJjEhRrbumSnKnZLn
frh8OXYd4nP9cDdQTXP+oo1BEWzRDF1VFSmZj7WuwuhO9ch3Cw96IWOZhCYzN4nO
MGErk90toc7ATEblYRHAEnpCWNA6MyKYbW+JWg84GBwY4vm+Os+FAgMBAAE=
-----END RSA PUBLIC KEY-----

I don't know exactly when I downloaded this or from whom I downloaded it, so it will be difficult to debug this.

Forgot to mention that the cached-microdescs.new file Tor's using has duplicate entries. Should there be duplicate entries?

$ grep "^MI" ~/.tor/cached-microdescs.newold | sort | uniq -cd
      2 MIGJAoGBAKHkrgqf576iQMzOIzmS0Z+rjTh2Q3v936L3zqawNcuSXcy7RKPbdgiK
      2 MIGJAoGBAKIXGw0frrUg6zR7qOEWHxSZGGqw71hDoDcKgv6m3JDduNb0x2U40WGA
      2 MIGJAoGBAKnI/S/EA5uOXqOJfdUosD74i6mtcNNvUYIjCMnLJjEhRrbumSnKnZLn
      2 MIGJAoGBAKoUyVw/AA78Zo3yBiiXUH86kqy+2WNVFgCnX3gBOWjljNF0hW4w7waN
      2 MIGJAoGBAMM7lzyPlR6I43HrwR3L3IxUyWx66rXs/M+gJWHkCdxn86G0E3VbhVzB
      2 MIGJAoGBAMpjsCEz4sRS7VQIDElsKFxqdkhP4gjMnFicgBZGl8jN3t1skWzi6C2B
      2 MIGJAoGBAOTCaE2ghD8hCWFpeZLWOAomxO3f7t4vUmeOtcMW7TiVyhjbU1Rolu8I
      2 MIGJAoGBAOUwYzUaqe03XsGptgdkMRAiTM431dHxnAW2XUhxbQHfh7lkNMSI5x9e

And thinking about this a little more

@last-listed 2013-01-15 07:13:33
onion-key
-----BEGIN RSA PUBLIC KEY-----
MIGJAoGBAKHkrgqf576iQMzOIzmS0Z+rjTh2Q3v936L3zqawNcuSXcy7RKPbdgiK
b8nmS4xm57buohWKXR25@last-listed 2013-01-15 08:32:48
onion-key
-----BEGIN RSA PUBLIC KEY-----

So this is from earlier today, silly me. Interestingly, but not surprisingly, I renamed this cached file and downloaded a new one and it does not have malformed entries. It does still have a few dupes, this may be tangential to this bug, though.

$ grep "^MI" ~/.tor/cached-microdescs.new | sort | uniq -cd | less
      2 MIGJAoGBAKcYw4VsCIqDdSz1sGsgfGxhO8JL71O+lRie5sXFD40DIyRH1Evl5Pir
      2 MIGJAoGBANGyUJt13wAm75tjGJMec3QgOlNvh7KXYX6Zy9QYj+DfWRkuuZWZ+XLZ
      2 MIGJAoGBAOzTLfKjUVUIwnqLTPq5o6O+B9ESiqPQbTrEY8XW3UgxoERKcjbWX4Q4

All of these cases looks like a partially written microdescriptor with another microdescriptor jammed after it. I think the next step is to make the log message be a little more clear about where the error is being observed -- what we're parsing when we hit this error. I'd bet that it's cached-microdescriptors.new.

Trac:
Milestone: N/A to Tor: 0.2.4.x-final

Should there be duplicate entries?

This grep shows duplicates of onion keys only. Microdesc may consist policy and family too, if it was changed by relay then md generated by auth was changed too, but may still contain the same onion key.

jamming of microdescriptors may related to #8031 (moved)

I concur; this is probably another manifestation of #8031 (moved), now in needs_review.

Closing as duplicate of #8031 (moved).

Trac:
Resolution: N/A to duplicate
Status: new to closed

closed

moved to tpo/core/tor#7845 (closed)