search

keybase / client

Keybase Go Library, Client, Service, OS X, iOS, Android, Electron
BSD 3-Clause "New" or "Revised" License
8.89k stars 1.23k forks source link

pgp decryption is broken in standalone or on new server sessions #680

Closed maxtaco closed 9 years ago

maxtaco commented 9 years ago

Here is what I did:

keybase status

Username: max333
User ID: 8c26e674d0eaec3bc6b8f2f3554dad19
Device ID: 04902624774fa7042f9abdfa6372d218
Public keys:
    0101258d23e95bf6ec58a56e3aeb343925d8114b9070a3b0abce17ef2afecd87dcad0a (eldest)
        PGP Fingerprint: B78F 94CA 1696 35EF AEE0 0750 F532 BF57 CACD 6B00
        PGP Identities:
            keybase.io/max333 <max333@keybase.io>
        Created: 2015-08-21 10:56:25 -0400 EDT
        Expires: 1969-12-31 19:00:00 -0500 EST
    01200ce150f8c172838257a8e1bc4ab241dbe7e06ee8b18c3dfe649ffed26d73524d0a
        Device ID: 04902624774fa7042f9abdfa6372d218
        Device Description: work computer
        Created: 2015-08-21 10:57:34 -0400 EDT
        Expires: 2031-08-17 10:57:34 -0400 EDT
        Subkeys:
            012101aec494aa93399f31d543a4b68019120f0206ba9a097b4becce43be43e6cb0d0a
                Created: 2015-08-21 10:57:34 -0400 EDT
                Expires: 2031-08-17 10:57:34 -0400 EDT
    01207b78d3d6d7fd971b5377c032be89a43eaabfe537cfb9cc561eeb8181ac90a27a0a
        Device ID: e5e1ff0cfff2e141f09c60a89add9618
        Device Description: Paper Key (april scout ...)
        Created: 2015-08-21 10:57:34 -0400 EDT
        Expires: 2031-08-17 10:57:34 -0400 EDT
        Subkeys:
            0121eaf6a5183daf3a4471f52a0e234f8fe5c5f87ad19af08cd6e56a9dda14dd99160a
                Created: 2015-08-21 10:57:34 -0400 EDT
                Expires: 2031-08-17 10:57:34 -0400 EDT
    01013f2e92356b5beffbb906e3a57937646df8769ee330352c5a2d943cdbf714d0c10a
        PGP Fingerprint: CF55 C809 FF4C 9569 9514 15D1 97B0 9925 CD0B 9AF8
        PGP Identities:
            keybase.io/max333 <max333@keybase.io>
        Created: 2015-08-21 15:53:38 -0400 EDT
        Expires: 2031-08-17 15:53:38 -0400 EDT

So my first key was a PGP key and I later added a PGP key via pgp gen --multi.

Then I made a very simple encryption with GPG:

echo "hi" | gpg -r cd0b9af8 -e -a

Which output:

-----BEGIN PGP MESSAGE----- 
Comment: GPGTools - https://gpgtools.org

hQIMA01kD/2s7PHPARAAtFGSW197WVvZgRl/uG77ky4rCGxo80Oc7e83BAWb6+Cy
8rF28kH/ZPXe8I+mgyjnkMnVSZCMEK9e2NmnuWL/556xnlsC+UH8q7/1bT7t25BJ
Xz3+YNQmMEP93fRIbfs2aC1fmvuDrpLLhOAaC2c8snxrY4nrYdDoUWLWxW//h8fI
pULQmbEmL0bwGPEwPnhu/cQw6jruXNFQ35RdPC4imgm0i97+waFn55lj2zS2BrAF
1eJ4vuZXzQUHew63EVizA7elutLPF0pKs6No81HeCDLjacezYWDu0RtsAA53y16r
l3fvOoR7s6+Xjs+3SGzlclJRVbgyHsFiqlZLtqi5yRkiplfqw1npfSHktJuBI+Df
CCUhL/LLwcfLaVDnNSW/MaoVU5nS6QmwWvJDCwQNEVaDO2ogDPAqw+BOE9yTk+av
8A1ULCXn7NvhgANXJOESvfSrqEufObrIdkm8OR6+/1MOpYG78xDibGkNTfw4bfRH
hPvatjtByQA5hny4PISw37t03SRWsfK3cMy+jElkI1RDA8z8bGI3yW+9XKgRZAT0
GyX5wxywAfA+6d+Z3Wwwo7DiF2fcOUnv1mqbOcRxPa6arU8DXQ3TMHC0wsLclEbq
orEcQdo9+oUlJz37Hgq5VB7QSN1DXyvsHaz3y4jyoBMxxx24pHeUgTyDazC7Z7LS
NAGwasF5QGXCMFUFDfQutPKanrUocf2+FWTGwRJAww4C8+CG5wax4ZA00aZD8v0V
ROGAnB0=
=1MHC
-----END PGP MESSAGE-----

Then I tried to decrypt:

pbpaste | ~/src/go/bin/keybase --standalone -H ~/kbt3 pgp decrypt
▶ INFO Identifying max333 
▶ INFO identify run err: Cannot track yourself 
▶ WARN error finding keys for 4d640ffdacecf1cf: Cannot track yourself 
▶ ERRO Failure from server: unable to find decryption key for this message (error 901)

And with debug:

pbpaste | ~/src/go/bin/keybase --standalone -d -H ~/kbt3 pgp decrypt
16:22:18.234157 ▶ DEBU 001 + loading config file: /Users/max/kbt3/Library/Application Support/KeybaseDev/config.json
16:22:18.234249 ▶ DEBU 002 - successfully loaded config file
16:22:18.234299 ▶ DEBU 003 Config: mapping server -> 
16:22:18.234485 ▶ DEBU 004 Config: mapping server -> 
16:22:18.234569 ▶ DEBU 005 Config: mapping timers -> 
16:22:18.234583 ▶ DEBU 006 Keybase Command-Line App v1.0.0
16:22:18.234591 ▶ DEBU 007 - Built with go1.4.2
16:22:18.234596 ▶ DEBU 008 - Visit https://keybase.io for more details
16:22:18.234624 ▶ DEBU 009 + LoopbackListener.Dial
16:22:18.234673 ▶ DEBU 00a + LoopbackListener.Accept
16:22:18.234716 ▶ DEBU 00b - LoopbackListener.Accept -> <nil>
16:22:18.234727 ▶ DEBU 00c + LoopbackListener.Accept
16:22:18.234780 ▶ DEBU 00d - LoopbackListener.Dial
16:22:18.234848 ▶ DEBU 00e Config: mapping local_rpc_debug -> 
16:22:18.235441 ▶ DEBU 00f + Account "LoggedInLoad"
16:22:18.235494 ▶ DEBU 010 + Loading session
16:22:18.235539 ▶ DEBU 011 Config: mapping session_file -> 
16:22:18.235654 ▶ DEBU 012 Config: mapping session_file -> 
16:22:18.235678 ▶ DEBU 013 + loading session file: /Users/max/kbt3/Library/Caches/KeybaseDev/session.json
16:22:18.235734 ▶ DEBU 014 - successfully loaded session file
16:22:18.235755 ▶ DEBU 015 - Loaded session
16:22:18.235763 ▶ DEBU 016 + Checking session
16:22:18.235806 ▶ DEBU 017 + API GET request to http://localhost:3000/_/api/1.0/sesscheck.json
16:22:18.235861 ▶ DEBU 018 | Cli wasn't found; remaking for cookied=true
16:22:18.253106 ▶ DEBU 019 | Result is: 200 OK
16:22:18.253204 ▶ DEBU 01a - successful API call
16:22:18.253220 ▶ DEBU 01b | Stored session checked out
16:22:18.253240 ▶ DEBU 01c - Checked session
16:22:18.253263 ▶ DEBU 01d - Account "LoggedInLoad"
16:22:18.253284 ▶ DEBU 01e LoadUser: {UID: Name: PublicKeyOptional:false NoCacheResult:false Self:true ForceReload:false AllKeys:false LoginContext:<nil> Contextified:{g:<nil>}}
16:22:18.253441 ▶ DEBU 01f + Account "G - GetMyUID - GetUID"
16:22:18.253472 ▶ DEBU 020 - Account "G - GetMyUID - GetUID"
16:22:18.253487 ▶ DEBU 021 + LoadUser(uid=8c26e674d0eaec3bc6b8f2f3554dad19, name=)
16:22:18.253500 ▶ DEBU 022 | resolved to 8c26e674d0eaec3bc6b8f2f3554dad19
16:22:18.253522 ▶ DEBU 023 + LoadUserFromLocalStorage(8c26e674d0eaec3bc6b8f2f3554dad19)
16:22:18.253569 ▶ DEBU 024 Config: mapping db -> 
16:22:18.253619 ▶ DEBU 025 Opening LevelDB for local cache: /Users/max/kbt3/Library/Application Support/KeybaseDev/keybase.leveldb
16:22:18.257843 ▶ DEBU 026 | Loaded successfully
16:22:18.257878 ▶ DEBU 027 + ParseKeyFamily
16:22:18.261443 ▶ DEBU 028 - ParseKeyFamily -> ok
16:22:18.261485 ▶ DEBU 029 | Loaded username max333 (uid=8c26e674d0eaec3bc6b8f2f3554dad19)
16:22:18.261495 ▶ DEBU 02a - LoadUserFromLocalStorage(max333,8c26e674d0eaec3bc6b8f2f3554dad19)
16:22:18.261511 ▶ DEBU 02b + MerkleClient.LookupUser(map[uid:8c26e674d0eaec3bc6b8f2f3554dad19])
16:22:18.261529 ▶ DEBU 02c + MerkleClient.LoadRoot()
16:22:18.261921 ▶ DEBU 02d - MerkleClient.LoadRoot() -> 32647
16:22:18.261932 ▶ DEBU 02e | LookupPath
16:22:18.261956 ▶ DEBU 02f + API GET request to http://localhost:3000/_/api/1.0/merkle/path.json?poll=10&uid=8c26e674d0eaec3bc6b8f2f3554dad19
16:22:18.261975 ▶ DEBU 030 | Cli wasn't found; remaking for cookied=false
16:22:18.272738 ▶ DEBU 031 | Result is: 200 OK
16:22:18.274015 ▶ DEBU 032 - successful API call
16:22:18.274104 ▶ DEBU 033 | VerifyRoot
16:22:18.274120 ▶ DEBU 034 | Merkle root: got back 32647, >= cached 32647
16:22:18.274136 ▶ DEBU 035 + Merkle: using KID=0101be58b6c82db64f6ccabb05088db443c69f87d5d48857d709ed6f73948dabe67d0a for verifying server sig
16:22:18.274146 ▶ DEBU 036 + SpecialKeyRing.Load(0101be58b6c82db64f6ccabb05088db443c69f87d5d48857d709ed6f73948dabe67d0a)
16:22:18.274266 ▶ DEBU 037 | Load(0101be58b6c82db64f6ccabb05088db443c69f87d5d48857d709ed6f73948dabe67d0a) going to network
16:22:18.274293 ▶ DEBU 038 + API GET request to http://localhost:3000/_/api/1.0/key/special.json?kid=0101be58b6c82db64f6ccabb05088db443c69f87d5d48857d709ed6f73948dabe67d0a
16:22:18.276008 ▶ DEBU 039 | Result is: 200 OK
16:22:18.276145 ▶ DEBU 03a - successful API call
16:22:18.276791 ▶ DEBU 03b | Storing Key (fp=a05161510ee696601ba0ec7b3fd53b4871528cef, kid=0101be58b6c82db64f6ccabb05088db443c69f87d5d48857d709ed6f73948dabe67d0a) to Local DB
16:22:18.276921 ▶ DEBU 03c - SpecialKeyRing.Load(0101be58b6c82db64f6ccabb05088db443c69f87d5d48857d709ed6f73948dabe67d0a)
16:22:18.276933 ▶ DEBU 03d - Merkle: server sig verified
16:22:18.277272 ▶ DEBU 03e | VerifyUser
16:22:18.278614 ▶ DEBU 03f + ParsingMerkleUserLeaf
16:22:18.278697 ▶ DEBU 040 Merkle leaf json:
[
    2,
    [
        5,
        "cac9b043feaddca5d14fed037191a02b6f24979b488cc54a53abc79f96f50b92",
        "1fa982fc3d7f5eabf43a7e2296ad9e251dc6c6f92fcbc0d7946a3f4d7b2d33b5"
    ],
    [],
    "0101258d23e95bf6ec58a56e3aeb343925d8114b9070a3b0abce17ef2afecd87dcad0a"
]
16:22:18.278720 ▶ DEBU 041 - ParsingMerkleUserLeaf -> ok
16:22:18.278731 ▶ DEBU 042 | VerifyUsername
16:22:18.278742 ▶ DEBU 043 | Username max333 mapped to 8c26e674d0eaec3bc6b8f2f3554dad19 via direct hash
16:22:18.278751 ▶ DEBU 044 - MerkleClient.LookupUser(map[uid:8c26e674d0eaec3bc6b8f2f3554dad19 poll:10]) -> OK
16:22:18.278776 ▶ DEBU 045 | Local basics version is up-to-date @ version 6
16:22:18.278784 ▶ DEBU 046 | Freshness: basics=true; for 8c26e674d0eaec3bc6b8f2f3554dad19
16:22:18.278797 ▶ DEBU 047 + SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19)
16:22:18.278807 ▶ DEBU 048 | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) GetFingerprint
16:22:18.278816 ▶ DEBU 049 | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) AccessPreload
16:22:18.278824 ▶ DEBU 04a | Preload failed
16:22:18.278830 ▶ DEBU 04b | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) LoadLinksFromStorage
16:22:18.278837 ▶ DEBU 04c + SigChainLoader.LoadFromStorage(8c26e674d0eaec3bc6b8f2f3554dad19)
16:22:18.278933 ▶ DEBU 04d - SigChainLoader.LoadFromStorage(8c26e674d0eaec3bc6b8f2f3554dad19) -> ok
16:22:18.278944 ▶ DEBU 04e | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) MakeSigChain
16:22:18.278965 ▶ DEBU 04f | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) VerifyChain
16:22:18.278974 ▶ DEBU 050 + SigChain::VerifyChain()
16:22:18.278980 ▶ DEBU 051 - SigChain::VerifyChain() -> ok
16:22:18.278986 ▶ DEBU 052 | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) CheckFreshness
16:22:18.278995 ▶ DEBU 053 + CheckFreshness
16:22:18.279002 ▶ DEBU 054 | Server triple: &{5 cac9b043feaddca5d14fed037191a02b6f24979b488cc54a53abc79f96f50b92 1fa982fc3d7f5eabf43a7e2296ad9e251dc6c6f92fcbc0d7946a3f4d7b2d33b50f}
16:22:18.279021 ▶ DEBU 055 | Client triple=nil
16:22:18.279027 ▶ DEBU 056 | Future triple=nil
16:22:18.279033 ▶ DEBU 057 | Local chain version is out-of-date: -1 < 5
16:22:18.279040 ▶ DEBU 058 - CheckFreshness (8c26e674d0eaec3bc6b8f2f3554dad19) -> (false,ok)
16:22:18.279048 ▶ DEBU 059 | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) LoadFromServer
16:22:18.279055 ▶ DEBU 05a + GetLastLoadedSeqno()
16:22:18.279061 ▶ DEBU 05b - GetLastLoadedSeqno() -> 0
16:22:18.279067 ▶ DEBU 05c + Load SigChain from server (uid=8c26e674d0eaec3bc6b8f2f3554dad19, low=0)
16:22:18.279086 ▶ DEBU 05d + API GET request to http://localhost:3000/_/api/1.0/sig/get.json?low=0&uid=8c26e674d0eaec3bc6b8f2f3554dad19
16:22:18.302056 ▶ DEBU 05e | Result is: 200 OK
16:22:18.302930 ▶ DEBU 05f - successful API call
16:22:18.302951 ▶ DEBU 060 | Got back 5 new entries
16:22:18.303067 ▶ DEBU 061 | Unpacked Link c5be4a346213000e8ea152244269d5284addac7bec4da84587102930a02d087e
16:22:18.303181 ▶ DEBU 062 | Unpacked Link 7fac961c9ac43bb942e7428d23b3a3d49de92e5b79cf6c7724a67d8d04b61876
16:22:18.303339 ▶ DEBU 063 | Unpacked Link 4efbfd4cdcd8aac9b31a2e95e6dd381d25103dd8a684141c964d72c962304665
16:22:18.303460 ▶ DEBU 064 | Unpacked Link f586808e301cc5ceae0d9a0ee797c520da3d0451d09a6c81d1d425abf348a479
16:22:18.303646 ▶ DEBU 065 | Unpacked Link cac9b043feaddca5d14fed037191a02b6f24979b488cc54a53abc79f96f50b92
16:22:18.303664 ▶ DEBU 066 | Found chain tail advertised in Merkle tree @5
16:22:18.303674 ▶ DEBU 067 - Loaded SigChain -> ok
16:22:18.303687 ▶ DEBU 068 | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) VerifyChain
16:22:18.303699 ▶ DEBU 069 + SigChain::VerifyChain()
16:22:18.304621 ▶ DEBU 06a - SigChain::VerifyChain() -> ok
16:22:18.304644 ▶ DEBU 06b | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) Store
16:22:18.304774 ▶ DEBU 06c | Store Link cac9b043feaddca5d14fed037191a02b6f24979b488cc54a53abc79f96f50b92
16:22:18.304856 ▶ DEBU 06d | Store Link f586808e301cc5ceae0d9a0ee797c520da3d0451d09a6c81d1d425abf348a479
16:22:18.304944 ▶ DEBU 06e | Store Link 4efbfd4cdcd8aac9b31a2e95e6dd381d25103dd8a684141c964d72c962304665
16:22:18.305030 ▶ DEBU 06f | Store Link 7fac961c9ac43bb942e7428d23b3a3d49de92e5b79cf6c7724a67d8d04b61876
16:22:18.305180 ▶ DEBU 070 | Store Link c5be4a346213000e8ea152244269d5284addac7bec4da84587102930a02d087e
16:22:18.305196 ▶ DEBU 071 | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) VerifySig
16:22:18.305205 ▶ DEBU 072 VerifySigsAndComputeKeys(): l.leaf: &{0xc20826e450 <nil> 6 max333 8c26e674d0eaec3bc6b8f2f3554dad19 0101258d23e95bf6ec58a56e3aeb343925d8114b9070a3b0abce17ef2afecd87dcad0a}, l.leaf.eldest: 0101258d23e95bf6ec58a56e3aeb343925d8114b9070a3b0abce17ef2afecd87dcad0a, l.ckf: {0xc20802fcc0 <nil> {<nil>}}
16:22:18.305234 ▶ DEBU 073 + VerifySigsAndComputeKeys for user 8c26e674d0eaec3bc6b8f2f3554dad19 (eldest = 0101258d23e95bf6ec58a56e3aeb343925d8114b9070a3b0abce17ef2afecd87dcad0a)
16:22:18.305244 ▶ DEBU 074 + SigChain::VerifyChain()
16:22:18.305257 ▶ DEBU 075 - SigChain::VerifyChain() -> ok
16:22:18.305264 ▶ DEBU 076 + verifySubchain
16:22:18.305358 ▶ DEBU 077 | Verify link: c5be4a346213000e8ea152244269d5284addac7bec4da84587102930a02d087e
16:22:18.305720 ▶ DEBU 078 ComputeKeyInfos::Delegate To 01200ce150f8c172838257a8e1bc4ab241dbe7e06ee8b18c3dfe649ffed26d73524d0a with 0101258d23e95bf6ec58a56e3aeb343925d8114b9070a3b0abce17ef2afecd87dcad0a at sig 6f0b8337281724beb910fbd205a74212e423938e0f25b47b52ed85ef642c9ca30f
16:22:18.306282 ▶ DEBU 079 + UpdateDevice
16:22:18.306294 ▶ DEBU 07a | Device ID=04902624774fa7042f9abdfa6372d218; KID=01200ce150f8c172838257a8e1bc4ab241dbe7e06ee8b18c3dfe649ffed26d73524d0a
16:22:18.306304 ▶ DEBU 07b | New insert
16:22:18.306312 ▶ DEBU 07c - UpdateDevice -> ok
16:22:18.306331 ▶ DEBU 07d | Verify link: 7fac961c9ac43bb942e7428d23b3a3d49de92e5b79cf6c7724a67d8d04b61876
16:22:18.306719 ▶ DEBU 07e ComputeKeyInfos::Delegate To 012101aec494aa93399f31d543a4b68019120f0206ba9a097b4becce43be43e6cb0d0a with 01200ce150f8c172838257a8e1bc4ab241dbe7e06ee8b18c3dfe649ffed26d73524d0a at sig 77fbf460884a291c5a9b0386f08116abbb5d9606e88f3faa615ef5ca483574dd0f
16:22:18.306739 ▶ DEBU 07f + UpdateDevice
16:22:18.306746 ▶ DEBU 080 - UpdateDevice -> ok
16:22:18.306779 ▶ DEBU 081 | Verify link: 4efbfd4cdcd8aac9b31a2e95e6dd381d25103dd8a684141c964d72c962304665
16:22:18.307186 ▶ DEBU 082 ComputeKeyInfos::Delegate To 01207b78d3d6d7fd971b5377c032be89a43eaabfe537cfb9cc561eeb8181ac90a27a0a with 01200ce150f8c172838257a8e1bc4ab241dbe7e06ee8b18c3dfe649ffed26d73524d0a at sig d113eaa6530f5c692dd6534a515066bb2c0e8713efa4c5b83a4bf57949530a120f
16:22:18.307669 ▶ DEBU 083 + UpdateDevice
16:22:18.307680 ▶ DEBU 084 | Device ID=e5e1ff0cfff2e141f09c60a89add9618; KID=01207b78d3d6d7fd971b5377c032be89a43eaabfe537cfb9cc561eeb8181ac90a27a0a
16:22:18.307688 ▶ DEBU 085 | New insert
16:22:18.307694 ▶ DEBU 086 - UpdateDevice -> ok
16:22:18.307706 ▶ DEBU 087 | Verify link: f586808e301cc5ceae0d9a0ee797c520da3d0451d09a6c81d1d425abf348a479
16:22:18.308080 ▶ DEBU 088 ComputeKeyInfos::Delegate To 0121eaf6a5183daf3a4471f52a0e234f8fe5c5f87ad19af08cd6e56a9dda14dd99160a with 01207b78d3d6d7fd971b5377c032be89a43eaabfe537cfb9cc561eeb8181ac90a27a0a at sig f9759713e1bb7f81d356a1b9078cc5acae3f8f66e30df5f6081d1f2a64db3ad90f
16:22:18.308102 ▶ DEBU 089 + UpdateDevice
16:22:18.308108 ▶ DEBU 08a - UpdateDevice -> ok
16:22:18.308130 ▶ DEBU 08b | Verify link: cac9b043feaddca5d14fed037191a02b6f24979b488cc54a53abc79f96f50b92
16:22:18.308600 ▶ DEBU 08c ComputeKeyInfos::Delegate To 01013f2e92356b5beffbb906e3a57937646df8769ee330352c5a2d943cdbf714d0c10a with 01200ce150f8c172838257a8e1bc4ab241dbe7e06ee8b18c3dfe649ffed26d73524d0a at sig 1fa982fc3d7f5eabf43a7e2296ad9e251dc6c6f92fcbc0d7946a3f4d7b2d33b50f
16:22:18.309187 ▶ DEBU 08d + UpdateDevice
16:22:18.309200 ▶ DEBU 08e - UpdateDevice -> ok
16:22:18.309207 ▶ DEBU 08f Caching SigCheck for link cac9b043feaddca5d14fed037191a02b6f24979b488cc54a53abc79f96f50b92:
16:22:18.309215 ▶ DEBU 090 - verifySubchain -> false, ok
16:22:18.309222 ▶ DEBU 091 - VerifySigsAndComputeKeys for user 8c26e674d0eaec3bc6b8f2f3554dad19 -> ok
16:22:18.309230 ▶ DEBU 092 | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) Store
16:22:18.309292 ▶ DEBU 093 | Storing dirtyTail @ 5 (&{5 cac9b043feaddca5d14fed037191a02b6f24979b488cc54a53abc79f96f50b92 })
16:22:18.309615 ▶ DEBU 094 | Store Link cac9b043feaddca5d14fed037191a02b6f24979b488cc54a53abc79f96f50b92
16:22:18.309629 ▶ DEBU 095 - SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) -> (true, ok)
16:22:18.309642 ▶ DEBU 096 + LoadSigHints(8c26e674d0eaec3bc6b8f2f3554dad19)
16:22:18.309694 ▶ DEBU 097 | SigHints loaded @v0
16:22:18.309703 ▶ DEBU 098 - LoadSigHints(8c26e674d0eaec3bc6b8f2f3554dad19)
16:22:18.309710 ▶ DEBU 099 + Refresh SigHints() for uid=8c26e674d0eaec3bc6b8f2f3554dad19
16:22:18.309736 ▶ DEBU 09a + API GET request to http://localhost:3000/_/api/1.0/sig/hints.json?low=0&uid=8c26e674d0eaec3bc6b8f2f3554dad19
16:22:18.312889 ▶ DEBU 09b | Result is: 200 OK
16:22:18.312976 ▶ DEBU 09c - successful API call
16:22:18.312993 ▶ DEBU 09d | No changes; version 0 was up-to-date
16:22:18.313020 ▶ DEBU 09e - Refresh SigHints() for uid=8c26e674d0eaec3bc6b8f2f3554dad19
16:22:18.313045 ▶ DEBU 09f + Store user max333
16:22:18.313059 ▶ DEBU 0a0 + SigHints.Store() for uid=8c26e674d0eaec3bc6b8f2f3554dad19
16:22:18.313091 ▶ DEBU 0a1 | SigHints.Store() skipped; wasn't dirty
16:22:18.313102 ▶ DEBU 0a2 - SigHints.Store() for uid=8c26e674d0eaec3bc6b8f2f3554dad19 -> ok
16:22:18.313113 ▶ DEBU 0a3 - Store for max333 skipped; user wasn't dirty
16:22:18.313140 ▶ DEBU 0a4 + Populate ID Table
16:22:18.313190 ▶ DEBU 0a5 - Populate ID Table
16:22:18.313201 ▶ DEBU 0a6 + VerifySelfSig for user max333
16:22:18.313245 ▶ DEBU 0a7 | Found self-signature for max333 @uid=8c26e674d0eaec3bc6b8f2f3554dad19, seq=5, link=cac9b043feaddca5d14fed037191a02b6f24979b488cc54a53abc79f96f50b92
16:22:18.313278 ▶ DEBU 0a8 - VerifySelfSig via SigChain
16:22:18.313303 ▶ DEBU 0a9 + User.GetSyncedSecretKey()
16:22:18.313322 ▶ DEBU 0aa + Account "RunSecretSyncer"
16:22:18.313384 ▶ DEBU 0ab + Syncer.Load(8c26e674d0eaec3bc6b8f2f3554dad19)
16:22:18.313848 ▶ DEBU 0ac | loadFromStorage -> found=true, err=ok
16:22:18.313864 ▶ DEBU 0ad | Loaded version 5
16:22:18.313890 ▶ DEBU 0ae + API GET request to http://localhost:3000/_/api/1.0/key/fetch_private.json?version=5
16:22:18.330750 ▶ DEBU 0af | Result is: 200 OK
16:22:18.330825 ▶ DEBU 0b0 - successful API call
16:22:18.330837 ▶ DEBU 0b1 | syncFromServer -> ok
16:22:18.330887 ▶ DEBU 0b2 - Syncer.Load(8c26e674d0eaec3bc6b8f2f3554dad19) -> ok
16:22:18.330932 ▶ DEBU 0b3 - Account "RunSecretSyncer"
16:22:18.330957 ▶ DEBU 0b4 + Account "User - FindActiveKey"
16:22:18.330978 ▶ DEBU 0b5 + Loading session
16:22:18.330987 ▶ DEBU 0b6 - Skipped; already loaded
16:22:18.331587 ▶ DEBU 0b7 - Account "User - FindActiveKey"
16:22:18.331612 ▶ DEBU 0b8 - User.GetSyncedSecretKey() -> ok
16:22:18.331629 ▶ DEBU 0b9 + Account "NewScanKeys - extractKeys"
16:22:18.331653 ▶ DEBU 0ba - Account "NewScanKeys - extractKeys"
16:22:18.331938 ▶ DEBU 0bb ScanKeys:KeysById(5576599820793868751) => 0 keys match in memory
16:22:18.331993 ▶ DEBU 0bc + API GET request to http://localhost:3000/_/api/1.0/key/basics.json?pgp_key_id=4d640ffdacecf1cf
16:22:18.335284 ▶ DEBU 0bd | Result is: 200 OK
16:22:18.335359 ▶ DEBU 0be key id 5576599820793868751 (4d640ffdacecf1cf) => max333, 8c26e674d0eaec3bc6b8f2f3554dad19
16:22:18.335402 ▶ DEBU 0bf + Account "LoggedInLoad"
16:22:18.335427 ▶ DEBU 0c0 + Loading session
16:22:18.335439 ▶ DEBU 0c1 - Skipped; already loaded
16:22:18.335447 ▶ DEBU 0c2 + Checking session
16:22:18.335456 ▶ DEBU 0c3 - already checked, short-circuting
16:22:18.335469 ▶ DEBU 0c4 - Account "LoggedInLoad"
16:22:18.335483 ▶ DEBU 0c5 LoadUser: {UID: Name: PublicKeyOptional:false NoCacheResult:false Self:true ForceReload:false AllKeys:false LoginContext:<nil> Contextified:{g:<nil>}}
16:22:18.335513 ▶ DEBU 0c6 + Account "G - GetMyUID - GetUID"
16:22:18.335531 ▶ DEBU 0c7 - Account "G - GetMyUID - GetUID"
16:22:18.335543 ▶ DEBU 0c8 + LoadUser(uid=8c26e674d0eaec3bc6b8f2f3554dad19, name=)
16:22:18.335554 ▶ DEBU 0c9 | resolved to 8c26e674d0eaec3bc6b8f2f3554dad19
16:22:18.335575 ▶ DEBU 0ca + LoadUserFromLocalStorage(8c26e674d0eaec3bc6b8f2f3554dad19)
16:22:18.336393 ▶ DEBU 0cb | Loaded successfully
16:22:18.336421 ▶ DEBU 0cc + ParseKeyFamily
16:22:18.339182 ▶ DEBU 0cd - ParseKeyFamily -> ok
16:22:18.339230 ▶ DEBU 0ce | Loaded username max333 (uid=8c26e674d0eaec3bc6b8f2f3554dad19)
16:22:18.339240 ▶ DEBU 0cf - LoadUserFromLocalStorage(max333,8c26e674d0eaec3bc6b8f2f3554dad19)
16:22:18.339249 ▶ DEBU 0d0 + MerkleClient.LookupUser(map[uid:8c26e674d0eaec3bc6b8f2f3554dad19])
16:22:18.339264 ▶ DEBU 0d1 + MerkleClient.LoadRoot()
16:22:18.339387 ▶ DEBU 0d2 - MerkleClient.LoadRoot() -> 32647
16:22:18.339407 ▶ DEBU 0d3 | LookupPath
16:22:18.339425 ▶ DEBU 0d4 + API GET request to http://localhost:3000/_/api/1.0/merkle/path.json?poll=10&uid=8c26e674d0eaec3bc6b8f2f3554dad19
16:22:18.345681 ▶ DEBU 0d5 | Result is: 200 OK
16:22:18.346841 ▶ DEBU 0d6 - successful API call
16:22:18.346958 ▶ DEBU 0d7 | VerifyRoot
16:22:18.346972 ▶ DEBU 0d8 | Merkle root: got back 32647, >= cached 32647
16:22:18.346986 ▶ DEBU 0d9 | VerifyUser
16:22:18.348154 ▶ DEBU 0da + ParsingMerkleUserLeaf
16:22:18.348194 ▶ DEBU 0db Merkle leaf json:
[
    2,
    [
        5,
        "cac9b043feaddca5d14fed037191a02b6f24979b488cc54a53abc79f96f50b92",
        "1fa982fc3d7f5eabf43a7e2296ad9e251dc6c6f92fcbc0d7946a3f4d7b2d33b5"
    ],
    [],
    "0101258d23e95bf6ec58a56e3aeb343925d8114b9070a3b0abce17ef2afecd87dcad0a"
]
16:22:18.348205 ▶ DEBU 0dc - ParsingMerkleUserLeaf -> ok
16:22:18.348212 ▶ DEBU 0dd | VerifyUsername
16:22:18.348222 ▶ DEBU 0de | Username max333 mapped to 8c26e674d0eaec3bc6b8f2f3554dad19 via direct hash
16:22:18.348230 ▶ DEBU 0df - MerkleClient.LookupUser(map[uid:8c26e674d0eaec3bc6b8f2f3554dad19 poll:10]) -> OK
16:22:18.348250 ▶ DEBU 0e0 | Local basics version is up-to-date @ version 6
16:22:18.348256 ▶ DEBU 0e1 | Freshness: basics=true; for 8c26e674d0eaec3bc6b8f2f3554dad19
16:22:18.348265 ▶ DEBU 0e2 + SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19)
16:22:18.348272 ▶ DEBU 0e3 | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) GetFingerprint
16:22:18.348279 ▶ DEBU 0e4 | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) AccessPreload
16:22:18.348293 ▶ DEBU 0e5 | Preload failed
16:22:18.348299 ▶ DEBU 0e6 | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) LoadLinksFromStorage
16:22:18.348306 ▶ DEBU 0e7 + SigChainLoader.LoadFromStorage(8c26e674d0eaec3bc6b8f2f3554dad19)
16:22:18.348338 ▶ DEBU 0e8 - SigChainLoader.LoadFromStorage(8c26e674d0eaec3bc6b8f2f3554dad19) -> ok
16:22:18.348353 ▶ DEBU 0e9 | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) MakeSigChain
16:22:18.348360 ▶ DEBU 0ea | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) VerifyChain
16:22:18.348366 ▶ DEBU 0eb + SigChain::VerifyChain()
16:22:18.348372 ▶ DEBU 0ec - SigChain::VerifyChain() -> ok
16:22:18.348379 ▶ DEBU 0ed | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) CheckFreshness
16:22:18.348386 ▶ DEBU 0ee + CheckFreshness
16:22:18.348392 ▶ DEBU 0ef | Server triple: &{5 cac9b043feaddca5d14fed037191a02b6f24979b488cc54a53abc79f96f50b92 1fa982fc3d7f5eabf43a7e2296ad9e251dc6c6f92fcbc0d7946a3f4d7b2d33b50f}
16:22:18.348410 ▶ DEBU 0f0 | Client triple=nil
16:22:18.348415 ▶ DEBU 0f1 | Future triple=nil
16:22:18.348421 ▶ DEBU 0f2 | Local chain version is out-of-date: -1 < 5
16:22:18.348428 ▶ DEBU 0f3 - CheckFreshness (8c26e674d0eaec3bc6b8f2f3554dad19) -> (false,ok)
16:22:18.348435 ▶ DEBU 0f4 | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) LoadFromServer
16:22:18.348442 ▶ DEBU 0f5 + GetLastLoadedSeqno()
16:22:18.348448 ▶ DEBU 0f6 - GetLastLoadedSeqno() -> 0
16:22:18.348454 ▶ DEBU 0f7 + Load SigChain from server (uid=8c26e674d0eaec3bc6b8f2f3554dad19, low=0)
16:22:18.348472 ▶ DEBU 0f8 + API GET request to http://localhost:3000/_/api/1.0/sig/get.json?low=0&uid=8c26e674d0eaec3bc6b8f2f3554dad19
16:22:18.353539 ▶ DEBU 0f9 | Result is: 200 OK
16:22:18.354520 ▶ DEBU 0fa - successful API call
16:22:18.354553 ▶ DEBU 0fb | Got back 5 new entries
16:22:18.354722 ▶ DEBU 0fc | Unpacked Link c5be4a346213000e8ea152244269d5284addac7bec4da84587102930a02d087e
16:22:18.354830 ▶ DEBU 0fd | Unpacked Link 7fac961c9ac43bb942e7428d23b3a3d49de92e5b79cf6c7724a67d8d04b61876
16:22:18.354947 ▶ DEBU 0fe | Unpacked Link 4efbfd4cdcd8aac9b31a2e95e6dd381d25103dd8a684141c964d72c962304665
16:22:18.355072 ▶ DEBU 0ff | Unpacked Link f586808e301cc5ceae0d9a0ee797c520da3d0451d09a6c81d1d425abf348a479
16:22:18.355192 ▶ DEBU 100 | Unpacked Link cac9b043feaddca5d14fed037191a02b6f24979b488cc54a53abc79f96f50b92
16:22:18.355203 ▶ DEBU 101 | Found chain tail advertised in Merkle tree @5
16:22:18.355212 ▶ DEBU 102 - Loaded SigChain -> ok
16:22:18.355219 ▶ DEBU 103 | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) VerifyChain
16:22:18.355227 ▶ DEBU 104 + SigChain::VerifyChain()
16:22:18.355957 ▶ DEBU 105 - SigChain::VerifyChain() -> ok
16:22:18.355983 ▶ DEBU 106 | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) Store
16:22:18.356233 ▶ DEBU 107 | Store Link cac9b043feaddca5d14fed037191a02b6f24979b488cc54a53abc79f96f50b92
16:22:18.356334 ▶ DEBU 108 | Store Link f586808e301cc5ceae0d9a0ee797c520da3d0451d09a6c81d1d425abf348a479
16:22:18.356434 ▶ DEBU 109 | Store Link 4efbfd4cdcd8aac9b31a2e95e6dd381d25103dd8a684141c964d72c962304665
16:22:18.356512 ▶ DEBU 10a | Store Link 7fac961c9ac43bb942e7428d23b3a3d49de92e5b79cf6c7724a67d8d04b61876
16:22:18.356676 ▶ DEBU 10b | Store Link c5be4a346213000e8ea152244269d5284addac7bec4da84587102930a02d087e
16:22:18.356693 ▶ DEBU 10c | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) VerifySig
16:22:18.356704 ▶ DEBU 10d VerifySigsAndComputeKeys(): l.leaf: &{0xc2084277a0 <nil> 6 max333 8c26e674d0eaec3bc6b8f2f3554dad19 0101258d23e95bf6ec58a56e3aeb343925d8114b9070a3b0abce17ef2afecd87dcad0a}, l.leaf.eldest: 0101258d23e95bf6ec58a56e3aeb343925d8114b9070a3b0abce17ef2afecd87dcad0a, l.ckf: {0xc2083a2960 <nil> {<nil>}}
16:22:18.356730 ▶ DEBU 10e + VerifySigsAndComputeKeys for user 8c26e674d0eaec3bc6b8f2f3554dad19 (eldest = 0101258d23e95bf6ec58a56e3aeb343925d8114b9070a3b0abce17ef2afecd87dcad0a)
16:22:18.356740 ▶ DEBU 10f + SigChain::VerifyChain()
16:22:18.356746 ▶ DEBU 110 - SigChain::VerifyChain() -> ok
16:22:18.356754 ▶ DEBU 111 + verifySubchain
16:22:18.356833 ▶ DEBU 112 | Verify link: c5be4a346213000e8ea152244269d5284addac7bec4da84587102930a02d087e
16:22:18.357198 ▶ DEBU 113 ComputeKeyInfos::Delegate To 01200ce150f8c172838257a8e1bc4ab241dbe7e06ee8b18c3dfe649ffed26d73524d0a with 0101258d23e95bf6ec58a56e3aeb343925d8114b9070a3b0abce17ef2afecd87dcad0a at sig 6f0b8337281724beb910fbd205a74212e423938e0f25b47b52ed85ef642c9ca30f
16:22:18.357735 ▶ DEBU 114 + UpdateDevice
16:22:18.357745 ▶ DEBU 115 | Device ID=04902624774fa7042f9abdfa6372d218; KID=01200ce150f8c172838257a8e1bc4ab241dbe7e06ee8b18c3dfe649ffed26d73524d0a
16:22:18.357765 ▶ DEBU 116 | New insert
16:22:18.357777 ▶ DEBU 117 - UpdateDevice -> ok
16:22:18.357803 ▶ DEBU 118 | Verify link: 7fac961c9ac43bb942e7428d23b3a3d49de92e5b79cf6c7724a67d8d04b61876
16:22:18.358182 ▶ DEBU 119 ComputeKeyInfos::Delegate To 012101aec494aa93399f31d543a4b68019120f0206ba9a097b4becce43be43e6cb0d0a with 01200ce150f8c172838257a8e1bc4ab241dbe7e06ee8b18c3dfe649ffed26d73524d0a at sig 77fbf460884a291c5a9b0386f08116abbb5d9606e88f3faa615ef5ca483574dd0f
16:22:18.358201 ▶ DEBU 11a + UpdateDevice
16:22:18.358207 ▶ DEBU 11b - UpdateDevice -> ok
16:22:18.358245 ▶ DEBU 11c | Verify link: 4efbfd4cdcd8aac9b31a2e95e6dd381d25103dd8a684141c964d72c962304665
16:22:18.358762 ▶ DEBU 11d ComputeKeyInfos::Delegate To 01207b78d3d6d7fd971b5377c032be89a43eaabfe537cfb9cc561eeb8181ac90a27a0a with 01200ce150f8c172838257a8e1bc4ab241dbe7e06ee8b18c3dfe649ffed26d73524d0a at sig d113eaa6530f5c692dd6534a515066bb2c0e8713efa4c5b83a4bf57949530a120f
16:22:18.359273 ▶ DEBU 11e + UpdateDevice
16:22:18.359284 ▶ DEBU 11f | Device ID=e5e1ff0cfff2e141f09c60a89add9618; KID=01207b78d3d6d7fd971b5377c032be89a43eaabfe537cfb9cc561eeb8181ac90a27a0a
16:22:18.359294 ▶ DEBU 120 | New insert
16:22:18.359301 ▶ DEBU 121 - UpdateDevice -> ok
16:22:18.359314 ▶ DEBU 122 | Verify link: f586808e301cc5ceae0d9a0ee797c520da3d0451d09a6c81d1d425abf348a479
16:22:18.359818 ▶ DEBU 123 ComputeKeyInfos::Delegate To 0121eaf6a5183daf3a4471f52a0e234f8fe5c5f87ad19af08cd6e56a9dda14dd99160a with 01207b78d3d6d7fd971b5377c032be89a43eaabfe537cfb9cc561eeb8181ac90a27a0a at sig f9759713e1bb7f81d356a1b9078cc5acae3f8f66e30df5f6081d1f2a64db3ad90f
16:22:18.359864 ▶ DEBU 124 + UpdateDevice
16:22:18.359874 ▶ DEBU 125 - UpdateDevice -> ok
16:22:18.359889 ▶ DEBU 126 | Verify link: cac9b043feaddca5d14fed037191a02b6f24979b488cc54a53abc79f96f50b92
16:22:18.360420 ▶ DEBU 127 ComputeKeyInfos::Delegate To 01013f2e92356b5beffbb906e3a57937646df8769ee330352c5a2d943cdbf714d0c10a with 01200ce150f8c172838257a8e1bc4ab241dbe7e06ee8b18c3dfe649ffed26d73524d0a at sig 1fa982fc3d7f5eabf43a7e2296ad9e251dc6c6f92fcbc0d7946a3f4d7b2d33b50f
16:22:18.361098 ▶ DEBU 128 + UpdateDevice
16:22:18.361111 ▶ DEBU 129 - UpdateDevice -> ok
16:22:18.361131 ▶ DEBU 12a Caching SigCheck for link cac9b043feaddca5d14fed037191a02b6f24979b488cc54a53abc79f96f50b92:
16:22:18.361144 ▶ DEBU 12b - verifySubchain -> false, ok
16:22:18.361153 ▶ DEBU 12c - VerifySigsAndComputeKeys for user 8c26e674d0eaec3bc6b8f2f3554dad19 -> ok
16:22:18.361162 ▶ DEBU 12d | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) Store
16:22:18.361225 ▶ DEBU 12e | Storing dirtyTail @ 5 (&{5 cac9b043feaddca5d14fed037191a02b6f24979b488cc54a53abc79f96f50b92 })
16:22:18.361549 ▶ DEBU 12f | Store Link cac9b043feaddca5d14fed037191a02b6f24979b488cc54a53abc79f96f50b92
16:22:18.361562 ▶ DEBU 130 - SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) -> (true, ok)
16:22:18.361571 ▶ DEBU 131 + LoadSigHints(8c26e674d0eaec3bc6b8f2f3554dad19)
16:22:18.361629 ▶ DEBU 132 | SigHints loaded @v0
16:22:18.361638 ▶ DEBU 133 - LoadSigHints(8c26e674d0eaec3bc6b8f2f3554dad19)
16:22:18.361649 ▶ DEBU 134 + Refresh SigHints() for uid=8c26e674d0eaec3bc6b8f2f3554dad19
16:22:18.361679 ▶ DEBU 135 + API GET request to http://localhost:3000/_/api/1.0/sig/hints.json?low=0&uid=8c26e674d0eaec3bc6b8f2f3554dad19
16:22:18.364798 ▶ DEBU 136 | Result is: 200 OK
16:22:18.364951 ▶ DEBU 137 - successful API call
16:22:18.364964 ▶ DEBU 138 | No changes; version 0 was up-to-date
16:22:18.364974 ▶ DEBU 139 - Refresh SigHints() for uid=8c26e674d0eaec3bc6b8f2f3554dad19
16:22:18.364982 ▶ DEBU 13a + Store user max333
16:22:18.364989 ▶ DEBU 13b + SigHints.Store() for uid=8c26e674d0eaec3bc6b8f2f3554dad19
16:22:18.364996 ▶ DEBU 13c | SigHints.Store() skipped; wasn't dirty
16:22:18.365003 ▶ DEBU 13d - SigHints.Store() for uid=8c26e674d0eaec3bc6b8f2f3554dad19 -> ok
16:22:18.365010 ▶ DEBU 13e - Store for max333 skipped; user wasn't dirty
16:22:18.365023 ▶ DEBU 13f + Populate ID Table
16:22:18.365105 ▶ DEBU 140 - Populate ID Table
16:22:18.365114 ▶ DEBU 141 + VerifySelfSig for user max333
16:22:18.365127 ▶ DEBU 142 | Found self-signature for max333 @uid=8c26e674d0eaec3bc6b8f2f3554dad19, seq=5, link=cac9b043feaddca5d14fed037191a02b6f24979b488cc54a53abc79f96f50b92
16:22:18.365134 ▶ DEBU 143 - VerifySelfSig via SigChain
16:22:18.365150 ▶ DEBU 144 tracking user "max333"
16:22:18.365180 ▶ DEBU 145 + Account "LoggedInLoad"
16:22:18.365209 ▶ DEBU 146 + Loading session
16:22:18.365217 ▶ DEBU 147 - Skipped; already loaded
16:22:18.365223 ▶ DEBU 148 + Checking session
16:22:18.365229 ▶ DEBU 149 - already checked, short-circuting
16:22:18.365238 ▶ DEBU 14a - Account "LoggedInLoad"
16:22:18.365250 ▶ DEBU 14b + Account "LoggedInLoad"
16:22:18.365261 ▶ DEBU 14c + Loading session
16:22:18.365267 ▶ DEBU 14d - Skipped; already loaded
16:22:18.365272 ▶ DEBU 14e + Checking session
16:22:18.365278 ▶ DEBU 14f - already checked, short-circuting
16:22:18.365285 ▶ DEBU 150 - Account "LoggedInLoad"
16:22:18.365388 ▶ DEBU 151 LoadUser: {UID: Name:keybase://max333 PublicKeyOptional:true NoCacheResult:false Self:false ForceReload:false AllKeys:false LoginContext:<nil> Contextified:{g:<nil>}}
16:22:18.365410 ▶ DEBU 152 + LoadUser(uid=, name=keybase://max333)
16:22:18.365421 ▶ DEBU 153 + Resolving username keybase://max333
16:22:18.365452 ▶ DEBU 154 + API GET request to http://localhost:3000/_/api/1.0/user/lookup.json?multi=1&username=max333
16:22:18.384126 ▶ DEBU 155 | Result is: 200 OK
16:22:18.384892 ▶ DEBU 156 - successful API call
16:22:18.384923 ▶ DEBU 157 + Account "G - GetMyUID - GetUID"
16:22:18.384966 ▶ DEBU 158 - Account "G - GetMyUID - GetUID"
16:22:18.386200 ▶ DEBU 159 | resolved to 8c26e674d0eaec3bc6b8f2f3554dad19
16:22:18.386232 ▶ DEBU 15a + LoadUserFromLocalStorage(8c26e674d0eaec3bc6b8f2f3554dad19)
16:22:18.386857 ▶ DEBU 15b | Loaded successfully
16:22:18.386878 ▶ DEBU 15c + ParseKeyFamily
16:22:18.389556 ▶ DEBU 15d - ParseKeyFamily -> ok
16:22:18.389589 ▶ DEBU 15e | Loaded username max333 (uid=8c26e674d0eaec3bc6b8f2f3554dad19)
16:22:18.389598 ▶ DEBU 15f - LoadUserFromLocalStorage(max333,8c26e674d0eaec3bc6b8f2f3554dad19)
16:22:18.389608 ▶ DEBU 160 + MerkleClient.LookupUser(map[uid:8c26e674d0eaec3bc6b8f2f3554dad19])
16:22:18.389628 ▶ DEBU 161 + MerkleClient.LoadRoot()
16:22:18.389749 ▶ DEBU 162 - MerkleClient.LoadRoot() -> 32647
16:22:18.389759 ▶ DEBU 163 | LookupPath
16:22:18.389777 ▶ DEBU 164 + API GET request to http://localhost:3000/_/api/1.0/merkle/path.json?poll=10&uid=8c26e674d0eaec3bc6b8f2f3554dad19
16:22:18.395654 ▶ DEBU 165 | Result is: 200 OK
16:22:18.396739 ▶ DEBU 166 - successful API call
16:22:18.396806 ▶ DEBU 167 | VerifyRoot
16:22:18.396815 ▶ DEBU 168 | Merkle root: got back 32647, >= cached 32647
16:22:18.396823 ▶ DEBU 169 | VerifyUser
16:22:18.397905 ▶ DEBU 16a + ParsingMerkleUserLeaf
16:22:18.397948 ▶ DEBU 16b Merkle leaf json:
[
    2,
    [
        5,
        "cac9b043feaddca5d14fed037191a02b6f24979b488cc54a53abc79f96f50b92",
        "1fa982fc3d7f5eabf43a7e2296ad9e251dc6c6f92fcbc0d7946a3f4d7b2d33b5"
    ],
    [],
    "0101258d23e95bf6ec58a56e3aeb343925d8114b9070a3b0abce17ef2afecd87dcad0a"
]
16:22:18.397959 ▶ DEBU 16c - ParsingMerkleUserLeaf -> ok
16:22:18.397966 ▶ DEBU 16d | VerifyUsername
16:22:18.397977 ▶ DEBU 16e | Username max333 mapped to 8c26e674d0eaec3bc6b8f2f3554dad19 via direct hash
16:22:18.397985 ▶ DEBU 16f - MerkleClient.LookupUser(map[uid:8c26e674d0eaec3bc6b8f2f3554dad19 poll:10]) -> OK
16:22:18.398004 ▶ DEBU 170 | Local basics version is up-to-date @ version 6
16:22:18.398011 ▶ DEBU 171 | Freshness: basics=true; for 8c26e674d0eaec3bc6b8f2f3554dad19
16:22:18.398019 ▶ DEBU 172 + SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19)
16:22:18.398027 ▶ DEBU 173 | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) GetFingerprint
16:22:18.398034 ▶ DEBU 174 | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) AccessPreload
16:22:18.398041 ▶ DEBU 175 | Preload failed
16:22:18.398047 ▶ DEBU 176 | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) LoadLinksFromStorage
16:22:18.398054 ▶ DEBU 177 + SigChainLoader.LoadFromStorage(8c26e674d0eaec3bc6b8f2f3554dad19)
16:22:18.398087 ▶ DEBU 178 - SigChainLoader.LoadFromStorage(8c26e674d0eaec3bc6b8f2f3554dad19) -> ok
16:22:18.398095 ▶ DEBU 179 | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) MakeSigChain
16:22:18.398104 ▶ DEBU 17a | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) VerifyChain
16:22:18.398111 ▶ DEBU 17b + SigChain::VerifyChain()
16:22:18.398117 ▶ DEBU 17c - SigChain::VerifyChain() -> ok
16:22:18.398124 ▶ DEBU 17d | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) CheckFreshness
16:22:18.398131 ▶ DEBU 17e + CheckFreshness
16:22:18.398137 ▶ DEBU 17f | Server triple: &{5 cac9b043feaddca5d14fed037191a02b6f24979b488cc54a53abc79f96f50b92 1fa982fc3d7f5eabf43a7e2296ad9e251dc6c6f92fcbc0d7946a3f4d7b2d33b50f}
16:22:18.398149 ▶ DEBU 180 | Client triple=nil
16:22:18.398155 ▶ DEBU 181 | Future triple=nil
16:22:18.398161 ▶ DEBU 182 | Local chain version is out-of-date: -1 < 5
16:22:18.398169 ▶ DEBU 183 - CheckFreshness (8c26e674d0eaec3bc6b8f2f3554dad19) -> (false,ok)
16:22:18.398176 ▶ DEBU 184 | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) LoadFromServer
16:22:18.398183 ▶ DEBU 185 + GetLastLoadedSeqno()
16:22:18.398190 ▶ DEBU 186 - GetLastLoadedSeqno() -> 0
16:22:18.398200 ▶ DEBU 187 + Load SigChain from server (uid=8c26e674d0eaec3bc6b8f2f3554dad19, low=0)
16:22:18.398223 ▶ DEBU 188 + API GET request to http://localhost:3000/_/api/1.0/sig/get.json?low=0&uid=8c26e674d0eaec3bc6b8f2f3554dad19
16:22:18.403323 ▶ DEBU 189 | Result is: 200 OK
16:22:18.404004 ▶ DEBU 18a - successful API call
16:22:18.404018 ▶ DEBU 18b | Got back 5 new entries
16:22:18.404112 ▶ DEBU 18c | Unpacked Link c5be4a346213000e8ea152244269d5284addac7bec4da84587102930a02d087e
16:22:18.404178 ▶ DEBU 18d | Unpacked Link 7fac961c9ac43bb942e7428d23b3a3d49de92e5b79cf6c7724a67d8d04b61876
16:22:18.404299 ▶ DEBU 18e | Unpacked Link 4efbfd4cdcd8aac9b31a2e95e6dd381d25103dd8a684141c964d72c962304665
16:22:18.404424 ▶ DEBU 18f | Unpacked Link f586808e301cc5ceae0d9a0ee797c520da3d0451d09a6c81d1d425abf348a479
16:22:18.404573 ▶ DEBU 190 | Unpacked Link cac9b043feaddca5d14fed037191a02b6f24979b488cc54a53abc79f96f50b92
16:22:18.404591 ▶ DEBU 191 | Found chain tail advertised in Merkle tree @5
16:22:18.404605 ▶ DEBU 192 - Loaded SigChain -> ok
16:22:18.404616 ▶ DEBU 193 | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) VerifyChain
16:22:18.404627 ▶ DEBU 194 + SigChain::VerifyChain()
16:22:18.405348 ▶ DEBU 195 - SigChain::VerifyChain() -> ok
16:22:18.405372 ▶ DEBU 196 | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) Store
16:22:18.405571 ▶ DEBU 197 | Store Link cac9b043feaddca5d14fed037191a02b6f24979b488cc54a53abc79f96f50b92
16:22:18.405727 ▶ DEBU 198 | Store Link f586808e301cc5ceae0d9a0ee797c520da3d0451d09a6c81d1d425abf348a479
16:22:18.405831 ▶ DEBU 199 | Store Link 4efbfd4cdcd8aac9b31a2e95e6dd381d25103dd8a684141c964d72c962304665
16:22:18.405897 ▶ DEBU 19a | Store Link 7fac961c9ac43bb942e7428d23b3a3d49de92e5b79cf6c7724a67d8d04b61876
16:22:18.405974 ▶ DEBU 19b | Store Link c5be4a346213000e8ea152244269d5284addac7bec4da84587102930a02d087e
16:22:18.405985 ▶ DEBU 19c | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) VerifySig
16:22:18.405994 ▶ DEBU 19d VerifySigsAndComputeKeys(): l.leaf: &{0xc208a10990 <nil> 6 max333 8c26e674d0eaec3bc6b8f2f3554dad19 0101258d23e95bf6ec58a56e3aeb343925d8114b9070a3b0abce17ef2afecd87dcad0a}, l.leaf.eldest: 0101258d23e95bf6ec58a56e3aeb343925d8114b9070a3b0abce17ef2afecd87dcad0a, l.ckf: {0xc208a3a6e0 <nil> {<nil>}}
16:22:18.406013 ▶ DEBU 19e + VerifySigsAndComputeKeys for user 8c26e674d0eaec3bc6b8f2f3554dad19 (eldest = 0101258d23e95bf6ec58a56e3aeb343925d8114b9070a3b0abce17ef2afecd87dcad0a)
16:22:18.406021 ▶ DEBU 19f + SigChain::VerifyChain()
16:22:18.406028 ▶ DEBU 1a0 - SigChain::VerifyChain() -> ok
16:22:18.406035 ▶ DEBU 1a1 + verifySubchain
16:22:18.406081 ▶ DEBU 1a2 | Verify link: c5be4a346213000e8ea152244269d5284addac7bec4da84587102930a02d087e
16:22:18.406406 ▶ DEBU 1a3 ComputeKeyInfos::Delegate To 01200ce150f8c172838257a8e1bc4ab241dbe7e06ee8b18c3dfe649ffed26d73524d0a with 0101258d23e95bf6ec58a56e3aeb343925d8114b9070a3b0abce17ef2afecd87dcad0a at sig 6f0b8337281724beb910fbd205a74212e423938e0f25b47b52ed85ef642c9ca30f
16:22:18.406970 ▶ DEBU 1a4 + UpdateDevice
16:22:18.406984 ▶ DEBU 1a5 | Device ID=04902624774fa7042f9abdfa6372d218; KID=01200ce150f8c172838257a8e1bc4ab241dbe7e06ee8b18c3dfe649ffed26d73524d0a
16:22:18.406993 ▶ DEBU 1a6 | New insert
16:22:18.407001 ▶ DEBU 1a7 - UpdateDevice -> ok
16:22:18.407016 ▶ DEBU 1a8 | Verify link: 7fac961c9ac43bb942e7428d23b3a3d49de92e5b79cf6c7724a67d8d04b61876
16:22:18.407416 ▶ DEBU 1a9 ComputeKeyInfos::Delegate To 012101aec494aa93399f31d543a4b68019120f0206ba9a097b4becce43be43e6cb0d0a with 01200ce150f8c172838257a8e1bc4ab241dbe7e06ee8b18c3dfe649ffed26d73524d0a at sig 77fbf460884a291c5a9b0386f08116abbb5d9606e88f3faa615ef5ca483574dd0f
16:22:18.407443 ▶ DEBU 1aa + UpdateDevice
16:22:18.407452 ▶ DEBU 1ab - UpdateDevice -> ok
16:22:18.407495 ▶ DEBU 1ac | Verify link: 4efbfd4cdcd8aac9b31a2e95e6dd381d25103dd8a684141c964d72c962304665
16:22:18.407928 ▶ DEBU 1ad ComputeKeyInfos::Delegate To 01207b78d3d6d7fd971b5377c032be89a43eaabfe537cfb9cc561eeb8181ac90a27a0a with 01200ce150f8c172838257a8e1bc4ab241dbe7e06ee8b18c3dfe649ffed26d73524d0a at sig d113eaa6530f5c692dd6534a515066bb2c0e8713efa4c5b83a4bf57949530a120f
16:22:18.408431 ▶ DEBU 1ae + UpdateDevice
16:22:18.408441 ▶ DEBU 1af | Device ID=e5e1ff0cfff2e141f09c60a89add9618; KID=01207b78d3d6d7fd971b5377c032be89a43eaabfe537cfb9cc561eeb8181ac90a27a0a
16:22:18.408450 ▶ DEBU 1b0 | New insert
16:22:18.408457 ▶ DEBU 1b1 - UpdateDevice -> ok
16:22:18.408470 ▶ DEBU 1b2 | Verify link: f586808e301cc5ceae0d9a0ee797c520da3d0451d09a6c81d1d425abf348a479
16:22:18.408839 ▶ DEBU 1b3 ComputeKeyInfos::Delegate To 0121eaf6a5183daf3a4471f52a0e234f8fe5c5f87ad19af08cd6e56a9dda14dd99160a with 01207b78d3d6d7fd971b5377c032be89a43eaabfe537cfb9cc561eeb8181ac90a27a0a at sig f9759713e1bb7f81d356a1b9078cc5acae3f8f66e30df5f6081d1f2a64db3ad90f
16:22:18.408857 ▶ DEBU 1b4 + UpdateDevice
16:22:18.408864 ▶ DEBU 1b5 - UpdateDevice -> ok
16:22:18.408879 ▶ DEBU 1b6 | Verify link: cac9b043feaddca5d14fed037191a02b6f24979b488cc54a53abc79f96f50b92
16:22:18.409324 ▶ DEBU 1b7 ComputeKeyInfos::Delegate To 01013f2e92356b5beffbb906e3a57937646df8769ee330352c5a2d943cdbf714d0c10a with 01200ce150f8c172838257a8e1bc4ab241dbe7e06ee8b18c3dfe649ffed26d73524d0a at sig 1fa982fc3d7f5eabf43a7e2296ad9e251dc6c6f92fcbc0d7946a3f4d7b2d33b50f
16:22:18.409860 ▶ DEBU 1b8 + UpdateDevice
16:22:18.409871 ▶ DEBU 1b9 - UpdateDevice -> ok
16:22:18.409879 ▶ DEBU 1ba Caching SigCheck for link cac9b043feaddca5d14fed037191a02b6f24979b488cc54a53abc79f96f50b92:
16:22:18.409890 ▶ DEBU 1bb - verifySubchain -> false, ok
16:22:18.409898 ▶ DEBU 1bc - VerifySigsAndComputeKeys for user 8c26e674d0eaec3bc6b8f2f3554dad19 -> ok
16:22:18.409907 ▶ DEBU 1bd | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) Store
16:22:18.409958 ▶ DEBU 1be | Storing dirtyTail @ 5 (&{5 cac9b043feaddca5d14fed037191a02b6f24979b488cc54a53abc79f96f50b92 })
16:22:18.410146 ▶ DEBU 1bf | Store Link cac9b043feaddca5d14fed037191a02b6f24979b488cc54a53abc79f96f50b92
16:22:18.410157 ▶ DEBU 1c0 - SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) -> (true, ok)
16:22:18.410165 ▶ DEBU 1c1 + LoadSigHints(8c26e674d0eaec3bc6b8f2f3554dad19)
16:22:18.410224 ▶ DEBU 1c2 | SigHints loaded @v0
16:22:18.410233 ▶ DEBU 1c3 - LoadSigHints(8c26e674d0eaec3bc6b8f2f3554dad19)
16:22:18.410240 ▶ DEBU 1c4 + Refresh SigHints() for uid=8c26e674d0eaec3bc6b8f2f3554dad19
16:22:18.410259 ▶ DEBU 1c5 + API GET request to http://localhost:3000/_/api/1.0/sig/hints.json?low=0&uid=8c26e674d0eaec3bc6b8f2f3554dad19
16:22:18.413961 ▶ DEBU 1c6 | Result is: 200 OK
16:22:18.414036 ▶ DEBU 1c7 - successful API call
16:22:18.414047 ▶ DEBU 1c8 | No changes; version 0 was up-to-date
16:22:18.414055 ▶ DEBU 1c9 - Refresh SigHints() for uid=8c26e674d0eaec3bc6b8f2f3554dad19
16:22:18.414064 ▶ DEBU 1ca + Store user max333
16:22:18.414070 ▶ DEBU 1cb + SigHints.Store() for uid=8c26e674d0eaec3bc6b8f2f3554dad19
16:22:18.414077 ▶ DEBU 1cc | SigHints.Store() skipped; wasn't dirty
16:22:18.414088 ▶ DEBU 1cd - SigHints.Store() for uid=8c26e674d0eaec3bc6b8f2f3554dad19 -> ok
16:22:18.414132 ▶ DEBU 1ce - Store for max333 skipped; user wasn't dirty
16:22:18.414148 ▶ DEBU 1cf + Populate ID Table
16:22:18.414183 ▶ DEBU 1d0 - Populate ID Table
16:22:18.414190 ▶ DEBU 1d1 + VerifySelfSig for user max333
16:22:18.414205 ▶ DEBU 1d2 | Found self-signature for max333 @uid=8c26e674d0eaec3bc6b8f2f3554dad19, seq=5, link=cac9b043feaddca5d14fed037191a02b6f24979b488cc54a53abc79f96f50b92
16:22:18.414214 ▶ DEBU 1d3 - VerifySelfSig via SigChain
16:22:18.414227 ▶ DEBU 1d4 + Account "LoggedInLoad"
16:22:18.414271 ▶ DEBU 1d5 + Loading session
16:22:18.414283 ▶ DEBU 1d6 - Skipped; already loaded
16:22:18.414293 ▶ DEBU 1d7 + Checking session
16:22:18.414318 ▶ DEBU 1d8 - already checked, short-circuting
16:22:18.414330 ▶ DEBU 1d9 - Account "LoggedInLoad"
16:22:18.414341 ▶ DEBU 1da LoadUser: {UID: Name: PublicKeyOptional:false NoCacheResult:false Self:true ForceReload:false AllKeys:false LoginContext:<nil> Contextified:{g:<nil>}}
16:22:18.414368 ▶ DEBU 1db + Account "G - GetMyUID - GetUID"
16:22:18.414390 ▶ DEBU 1dc - Account "G - GetMyUID - GetUID"
16:22:18.414402 ▶ DEBU 1dd + LoadUser(uid=8c26e674d0eaec3bc6b8f2f3554dad19, name=)
16:22:18.414413 ▶ DEBU 1de | resolved to 8c26e674d0eaec3bc6b8f2f3554dad19
16:22:18.414422 ▶ DEBU 1df + LoadUserFromLocalStorage(8c26e674d0eaec3bc6b8f2f3554dad19)
16:22:18.415048 ▶ DEBU 1e0 | Loaded successfully
16:22:18.415070 ▶ DEBU 1e1 + ParseKeyFamily
16:22:18.417556 ▶ DEBU 1e2 - ParseKeyFamily -> ok
16:22:18.417586 ▶ DEBU 1e3 | Loaded username max333 (uid=8c26e674d0eaec3bc6b8f2f3554dad19)
16:22:18.417595 ▶ DEBU 1e4 - LoadUserFromLocalStorage(max333,8c26e674d0eaec3bc6b8f2f3554dad19)
16:22:18.417605 ▶ DEBU 1e5 + MerkleClient.LookupUser(map[uid:8c26e674d0eaec3bc6b8f2f3554dad19])
16:22:18.417619 ▶ DEBU 1e6 + MerkleClient.LoadRoot()
16:22:18.417739 ▶ DEBU 1e7 - MerkleClient.LoadRoot() -> 32647
16:22:18.417749 ▶ DEBU 1e8 | LookupPath
16:22:18.417766 ▶ DEBU 1e9 + API GET request to http://localhost:3000/_/api/1.0/merkle/path.json?poll=10&uid=8c26e674d0eaec3bc6b8f2f3554dad19
16:22:18.425613 ▶ DEBU 1ea | Result is: 200 OK
16:22:18.426652 ▶ DEBU 1eb - successful API call
16:22:18.426717 ▶ DEBU 1ec | VerifyRoot
16:22:18.426726 ▶ DEBU 1ed | Merkle root: got back 32647, >= cached 32647
16:22:18.426735 ▶ DEBU 1ee | VerifyUser
16:22:18.427842 ▶ DEBU 1ef + ParsingMerkleUserLeaf
16:22:18.427911 ▶ DEBU 1f0 Merkle leaf json:
[
    2,
    [
        5,
        "cac9b043feaddca5d14fed037191a02b6f24979b488cc54a53abc79f96f50b92",
        "1fa982fc3d7f5eabf43a7e2296ad9e251dc6c6f92fcbc0d7946a3f4d7b2d33b5"
    ],
    [],
    "0101258d23e95bf6ec58a56e3aeb343925d8114b9070a3b0abce17ef2afecd87dcad0a"
]
16:22:18.427936 ▶ DEBU 1f1 - ParsingMerkleUserLeaf -> ok
16:22:18.427949 ▶ DEBU 1f2 | VerifyUsername
16:22:18.427966 ▶ DEBU 1f3 | Username max333 mapped to 8c26e674d0eaec3bc6b8f2f3554dad19 via direct hash
16:22:18.427979 ▶ DEBU 1f4 - MerkleClient.LookupUser(map[uid:8c26e674d0eaec3bc6b8f2f3554dad19 poll:10]) -> OK
16:22:18.428001 ▶ DEBU 1f5 | Local basics version is up-to-date @ version 6
16:22:18.428008 ▶ DEBU 1f6 | Freshness: basics=true; for 8c26e674d0eaec3bc6b8f2f3554dad19
16:22:18.428017 ▶ DEBU 1f7 + SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19)
16:22:18.428024 ▶ DEBU 1f8 | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) GetFingerprint
16:22:18.428032 ▶ DEBU 1f9 | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) AccessPreload
16:22:18.428039 ▶ DEBU 1fa | Preload failed
16:22:18.428044 ▶ DEBU 1fb | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) LoadLinksFromStorage
16:22:18.428052 ▶ DEBU 1fc + SigChainLoader.LoadFromStorage(8c26e674d0eaec3bc6b8f2f3554dad19)
16:22:18.428086 ▶ DEBU 1fd - SigChainLoader.LoadFromStorage(8c26e674d0eaec3bc6b8f2f3554dad19) -> ok
16:22:18.428094 ▶ DEBU 1fe | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) MakeSigChain
16:22:18.428102 ▶ DEBU 1ff | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) VerifyChain
16:22:18.428109 ▶ DEBU 200 + SigChain::VerifyChain()
16:22:18.428115 ▶ DEBU 201 - SigChain::VerifyChain() -> ok
16:22:18.428122 ▶ DEBU 202 | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) CheckFreshness
16:22:18.428130 ▶ DEBU 203 + CheckFreshness
16:22:18.428136 ▶ DEBU 204 | Server triple: &{5 cac9b043feaddca5d14fed037191a02b6f24979b488cc54a53abc79f96f50b92 1fa982fc3d7f5eabf43a7e2296ad9e251dc6c6f92fcbc0d7946a3f4d7b2d33b50f}
16:22:18.428149 ▶ DEBU 205 | Client triple=nil
16:22:18.428154 ▶ DEBU 206 | Future triple=nil
16:22:18.428160 ▶ DEBU 207 | Local chain version is out-of-date: -1 < 5
16:22:18.428167 ▶ DEBU 208 - CheckFreshness (8c26e674d0eaec3bc6b8f2f3554dad19) -> (false,ok)
16:22:18.428175 ▶ DEBU 209 | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) LoadFromServer
16:22:18.428182 ▶ DEBU 20a + GetLastLoadedSeqno()
16:22:18.428189 ▶ DEBU 20b - GetLastLoadedSeqno() -> 0
16:22:18.428195 ▶ DEBU 20c + Load SigChain from server (uid=8c26e674d0eaec3bc6b8f2f3554dad19, low=0)
16:22:18.428214 ▶ DEBU 20d + API GET request to http://localhost:3000/_/api/1.0/sig/get.json?low=0&uid=8c26e674d0eaec3bc6b8f2f3554dad19
16:22:18.434256 ▶ DEBU 20e | Result is: 200 OK
16:22:18.435181 ▶ DEBU 20f - successful API call
16:22:18.435205 ▶ DEBU 210 | Got back 5 new entries
16:22:18.435337 ▶ DEBU 211 | Unpacked Link c5be4a346213000e8ea152244269d5284addac7bec4da84587102930a02d087e
16:22:18.435438 ▶ DEBU 212 | Unpacked Link 7fac961c9ac43bb942e7428d23b3a3d49de92e5b79cf6c7724a67d8d04b61876
16:22:18.435581 ▶ DEBU 213 | Unpacked Link 4efbfd4cdcd8aac9b31a2e95e6dd381d25103dd8a684141c964d72c962304665
16:22:18.435649 ▶ DEBU 214 | Unpacked Link f586808e301cc5ceae0d9a0ee797c520da3d0451d09a6c81d1d425abf348a479
16:22:18.435743 ▶ DEBU 215 | Unpacked Link cac9b043feaddca5d14fed037191a02b6f24979b488cc54a53abc79f96f50b92
16:22:18.435752 ▶ DEBU 216 | Found chain tail advertised in Merkle tree @5
16:22:18.435760 ▶ DEBU 217 - Loaded SigChain -> ok
16:22:18.435768 ▶ DEBU 218 | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) VerifyChain
16:22:18.435775 ▶ DEBU 219 + SigChain::VerifyChain()
16:22:18.436437 ▶ DEBU 21a - SigChain::VerifyChain() -> ok
16:22:18.436454 ▶ DEBU 21b | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) Store
16:22:18.436589 ▶ DEBU 21c | Store Link cac9b043feaddca5d14fed037191a02b6f24979b488cc54a53abc79f96f50b92
16:22:18.436652 ▶ DEBU 21d | Store Link f586808e301cc5ceae0d9a0ee797c520da3d0451d09a6c81d1d425abf348a479
16:22:18.436732 ▶ DEBU 21e | Store Link 4efbfd4cdcd8aac9b31a2e95e6dd381d25103dd8a684141c964d72c962304665
16:22:18.436804 ▶ DEBU 21f | Store Link 7fac961c9ac43bb942e7428d23b3a3d49de92e5b79cf6c7724a67d8d04b61876
16:22:18.436926 ▶ DEBU 220 | Store Link c5be4a346213000e8ea152244269d5284addac7bec4da84587102930a02d087e
16:22:18.436938 ▶ DEBU 221 | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) VerifySig
16:22:18.436946 ▶ DEBU 222 VerifySigsAndComputeKeys(): l.leaf: &{0xc208345890 <nil> 6 max333 8c26e674d0eaec3bc6b8f2f3554dad19 0101258d23e95bf6ec58a56e3aeb343925d8114b9070a3b0abce17ef2afecd87dcad0a}, l.leaf.eldest: 0101258d23e95bf6ec58a56e3aeb343925d8114b9070a3b0abce17ef2afecd87dcad0a, l.ckf: {0xc20833b450 <nil> {<nil>}}
16:22:18.437238 ▶ DEBU 223 + VerifySigsAndComputeKeys for user 8c26e674d0eaec3bc6b8f2f3554dad19 (eldest = 0101258d23e95bf6ec58a56e3aeb343925d8114b9070a3b0abce17ef2afecd87dcad0a)
16:22:18.437254 ▶ DEBU 224 + SigChain::VerifyChain()
16:22:18.437265 ▶ DEBU 225 - SigChain::VerifyChain() -> ok
16:22:18.437277 ▶ DEBU 226 + verifySubchain
16:22:18.437333 ▶ DEBU 227 | Verify link: c5be4a346213000e8ea152244269d5284addac7bec4da84587102930a02d087e
16:22:18.437670 ▶ DEBU 228 ComputeKeyInfos::Delegate To 01200ce150f8c172838257a8e1bc4ab241dbe7e06ee8b18c3dfe649ffed26d73524d0a with 0101258d23e95bf6ec58a56e3aeb343925d8114b9070a3b0abce17ef2afecd87dcad0a at sig 6f0b8337281724beb910fbd205a74212e423938e0f25b47b52ed85ef642c9ca30f
16:22:18.438204 ▶ DEBU 229 + UpdateDevice
16:22:18.438218 ▶ DEBU 22a | Device ID=04902624774fa7042f9abdfa6372d218; KID=01200ce150f8c172838257a8e1bc4ab241dbe7e06ee8b18c3dfe649ffed26d73524d0a
16:22:18.438233 ▶ DEBU 22b | New insert
16:22:18.438244 ▶ DEBU 22c - UpdateDevice -> ok
16:22:18.438266 ▶ DEBU 22d | Verify link: 7fac961c9ac43bb942e7428d23b3a3d49de92e5b79cf6c7724a67d8d04b61876
16:22:18.438722 ▶ DEBU 22e ComputeKeyInfos::Delegate To 012101aec494aa93399f31d543a4b68019120f0206ba9a097b4becce43be43e6cb0d0a with 01200ce150f8c172838257a8e1bc4ab241dbe7e06ee8b18c3dfe649ffed26d73524d0a at sig 77fbf460884a291c5a9b0386f08116abbb5d9606e88f3faa615ef5ca483574dd0f
16:22:18.438753 ▶ DEBU 22f + UpdateDevice
16:22:18.438761 ▶ DEBU 230 - UpdateDevice -> ok
16:22:18.438801 ▶ DEBU 231 | Verify link: 4efbfd4cdcd8aac9b31a2e95e6dd381d25103dd8a684141c964d72c962304665
16:22:18.439351 ▶ DEBU 232 ComputeKeyInfos::Delegate To 01207b78d3d6d7fd971b5377c032be89a43eaabfe537cfb9cc561eeb8181ac90a27a0a with 01200ce150f8c172838257a8e1bc4ab241dbe7e06ee8b18c3dfe649ffed26d73524d0a at sig d113eaa6530f5c692dd6534a515066bb2c0e8713efa4c5b83a4bf57949530a120f
16:22:18.439867 ▶ DEBU 233 + UpdateDevice
16:22:18.439884 ▶ DEBU 234 | Device ID=e5e1ff0cfff2e141f09c60a89add9618; KID=01207b78d3d6d7fd971b5377c032be89a43eaabfe537cfb9cc561eeb8181ac90a27a0a
16:22:18.439893 ▶ DEBU 235 | New insert
16:22:18.439900 ▶ DEBU 236 - UpdateDevice -> ok
16:22:18.439914 ▶ DEBU 237 | Verify link: f586808e301cc5ceae0d9a0ee797c520da3d0451d09a6c81d1d425abf348a479
16:22:18.440286 ▶ DEBU 238 ComputeKeyInfos::Delegate To 0121eaf6a5183daf3a4471f52a0e234f8fe5c5f87ad19af08cd6e56a9dda14dd99160a with 01207b78d3d6d7fd971b5377c032be89a43eaabfe537cfb9cc561eeb8181ac90a27a0a at sig f9759713e1bb7f81d356a1b9078cc5acae3f8f66e30df5f6081d1f2a64db3ad90f
16:22:18.440306 ▶ DEBU 239 + UpdateDevice
16:22:18.440312 ▶ DEBU 23a - UpdateDevice -> ok
16:22:18.440327 ▶ DEBU 23b | Verify link: cac9b043feaddca5d14fed037191a02b6f24979b488cc54a53abc79f96f50b92
16:22:18.440750 ▶ DEBU 23c ComputeKeyInfos::Delegate To 01013f2e92356b5beffbb906e3a57937646df8769ee330352c5a2d943cdbf714d0c10a with 01200ce150f8c172838257a8e1bc4ab241dbe7e06ee8b18c3dfe649ffed26d73524d0a at sig 1fa982fc3d7f5eabf43a7e2296ad9e251dc6c6f92fcbc0d7946a3f4d7b2d33b50f
16:22:18.441323 ▶ DEBU 23d + UpdateDevice
16:22:18.441339 ▶ DEBU 23e - UpdateDevice -> ok
16:22:18.441347 ▶ DEBU 23f Caching SigCheck for link cac9b043feaddca5d14fed037191a02b6f24979b488cc54a53abc79f96f50b92:
16:22:18.441356 ▶ DEBU 240 - verifySubchain -> false, ok
16:22:18.441366 ▶ DEBU 241 - VerifySigsAndComputeKeys for user 8c26e674d0eaec3bc6b8f2f3554dad19 -> ok
16:22:18.441374 ▶ DEBU 242 | SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) Store
16:22:18.441468 ▶ DEBU 243 | Storing dirtyTail @ 5 (&{5 cac9b043feaddca5d14fed037191a02b6f24979b488cc54a53abc79f96f50b92 })
16:22:18.441716 ▶ DEBU 244 | Store Link cac9b043feaddca5d14fed037191a02b6f24979b488cc54a53abc79f96f50b92
16:22:18.441732 ▶ DEBU 245 - SigChainLoader.Load(8c26e674d0eaec3bc6b8f2f3554dad19) -> (true, ok)
16:22:18.441741 ▶ DEBU 246 + LoadSigHints(8c26e674d0eaec3bc6b8f2f3554dad19)
16:22:18.441775 ▶ DEBU 247 | SigHints loaded @v0
16:22:18.441784 ▶ DEBU 248 - LoadSigHints(8c26e674d0eaec3bc6b8f2f3554dad19)
16:22:18.441791 ▶ DEBU 249 + Refresh SigHints() for uid=8c26e674d0eaec3bc6b8f2f3554dad19
16:22:18.441811 ▶ DEBU 24a + API GET request to http://localhost:3000/_/api/1.0/sig/hints.json?low=0&uid=8c26e674d0eaec3bc6b8f2f3554dad19
16:22:18.444930 ▶ DEBU 24b | Result is: 200 OK
16:22:18.445046 ▶ DEBU 24c - successful API call
16:22:18.445064 ▶ DEBU 24d | No changes; version 0 was up-to-date
16:22:18.445078 ▶ DEBU 24e - Refresh SigHints() for uid=8c26e674d0eaec3bc6b8f2f3554dad19
16:22:18.445092 ▶ DEBU 24f + Store user max333
16:22:18.445104 ▶ DEBU 250 + SigHints.Store() for uid=8c26e674d0eaec3bc6b8f2f3554dad19
16:22:18.445117 ▶ DEBU 251 | SigHints.Store() skipped; wasn't dirty
16:22:18.445125 ▶ DEBU 252 - SigHints.Store() for uid=8c26e674d0eaec3bc6b8f2f3554dad19 -> ok
16:22:18.445154 ▶ DEBU 253 - Store for max333 skipped; user wasn't dirty
16:22:18.445187 ▶ DEBU 254 + Populate ID Table
16:22:18.445233 ▶ DEBU 255 - Populate ID Table
16:22:18.445245 ▶ DEBU 256 + VerifySelfSig for user max333
16:22:18.445265 ▶ DEBU 257 | Found self-signature for max333 @uid=8c26e674d0eaec3bc6b8f2f3554dad19, seq=5, link=cac9b043feaddca5d14fed037191a02b6f24979b488cc54a53abc79f96f50b92
16:22:18.445279 ▶ DEBU 258 - VerifySelfSig via SigChain
16:22:18.445495 ▶ DEBU 259 Config: mapping log_format -> 
16:22:18.445515 ▶ INFO 25a Identifying max333
16:22:18.445562 ▶ INFO 25b identify run err: Cannot track yourself
16:22:18.445581 ▶ WARN 25c error finding keys for 4d640ffdacecf1cf: Cannot track yourself
16:22:18.445733 ▶ DEBU 25d Closing LevelDB local cache: /Users/max/kbt3/Library/Application Support/KeybaseDev/keybase.leveldb
16:22:18.445949 ▶ DEBU 25e + Account "LoginState - Shutdown"
16:22:18.445981 ▶ DEBU 25f - Account "LoginState - Shutdown"
16:22:18.445996 ▶ ERRO 260 Failure from server: unable to find decryption key for this message (error 901)
maxtaco commented 9 years ago

Bug is on line 71 of scankeys, but not sure what's intended.

maxtaco commented 9 years ago

I take back what I said in my comment. I can workaround the issue by launching into server/client mode and making sure my passphrase stream is populated before running decrypt. If I do so, the error in #681 doesn't appear. So the failure here is inappropriately causing a failure in #681 which we should probably independently debug.