merge

8 files changed, 68 insertions, 4 deletions

diff --git a/src/cmd/auth/factotum/confirm.c b/src/cmd/auth/factotum/confirm.c
index 8f492450..105a46db 100644
--- a/src/cmd/auth/factotum/confirm.c
+++ b/src/cmd/auth/factotum/confirm.c
@@ -30,11 +30,13 @@ confirmwrite(char *s)
 		return -1;
 	}
 	if((t = _strfindattr(a, "tag")) == nil){
+		flog("bad confirm write: no tag");
 		werrstr("no tag");
 		return -1;
 	}
 	tag = strtoul(t, 0, 0);
 	if((ans = _strfindattr(a, "answer")) == nil){
+		flog("bad confirm write: no answer");
 		werrstr("no answer");
 		return -1;
 	}
@@ -43,6 +45,7 @@ confirmwrite(char *s)
 	else if(strcmp(ans, "no") == 0)
 		allow = 0;
 	else{
+		flog("bad confirm write: bad answer");
 		werrstr("bad answer");
 		return -1;
 	}
@@ -62,12 +65,17 @@ confirmwrite(char *s)
 int
 confirmkey(Conv *c, Key *k)
 {
+	int ret;
+
 	if(*confirminuse == 0)
 		return -1;
 
 	lbappend(&confbuf, "confirm tag=%lud %A %N", c->tag, k->attr, k->privattr);
+	flog("confirm %A %N", k->attr, k->privattr);
 	c->state = "keyconfirm";
-	return recvul(c->keywait);
+	ret = recvul(c->keywait);
+	flog("confirm=%d %A %N", ret, k->attr, k->privattr);
+	return ret;
 }
 
 Logbuf needkeybuf;
@@ -124,6 +132,7 @@ needkey(Conv *c, Attr *a)
 		return -1;
 
 	lbappend(&needkeybuf, "needkey tag=%lud %A", c->tag, a);
+	flog("needkey %A", a);
 	return nbrecvul(c->keywait);
 }
 
@@ -135,5 +144,7 @@ badkey(Conv *c, Key *k, char *msg, Attr *a)
 
 	lbappend(&needkeybuf, "badkey tag=%lud %A %N\n%s\n%A",
 		c->tag, k->attr, k->privattr, msg, a);
+	flog("badkey %A / %N / %s / %A",
+		k->attr, k->privattr, msg, a);
 	return nbrecvul(c->keywait);
 }
diff --git a/src/cmd/auth/factotum/conv.c b/src/cmd/auth/factotum/conv.c
index cd9d5045..1c92c06c 100644
--- a/src/cmd/auth/factotum/conv.c
+++ b/src/cmd/auth/factotum/conv.c
@@ -89,12 +89,14 @@ convgetrpc(Conv *c, int want)
 {
 	for(;;){
 		if(c->hangup){
+			flog("convgetrpc: hangup");
 			werrstr("hangup");
 			return nil;
 		}
 		if(c->rpc.op == RpcUnknown){
 			recvp(c->rpcwait);
 			if(c->hangup){
+				flog("convgetrpc: hangup");
 				werrstr("hangup");
 				return nil;
 			}
@@ -227,12 +229,27 @@ convneedkey(Conv *c, Attr *a)
 	 * in response.  The keys get added out-of-band (via the
 	 * ctl file), so assume the key has been added when the
 	 * next request comes in.
+	 *
+	 * The convgetrpc seems dodgy, because we might be in
+	 * the middle of an rpc, and what about the one that comes
+	 * in later?  It's all actually okay: convgetrpc is idempotent
+	 * until rpcrespond is called, so if we're in the middle of an rpc,
+	 * the first convgetrpc is a no-op, the rpcrespond sends back
+	 * the needkey, and then the client repeats the rpc we're in
+	 * the middle of.  Otherwise, if we're not in the middle of an
+	 * rpc, the first convgetrpc waits for one, we respond needkey,
+	 * and then the second convgetrpc waits for another.  Because
+	 * there is no second response, eventually the caller will get
+	 * around to asking for an rpc itself, at which point the already
+	 * gotten rpc will be returned again.
 	 */
 	if(convgetrpc(c, -1) == nil)
 		return -1;
+	flog("convneedkey %A", a);
 	rpcrespond(c, "needkey %A", a);
 	if(convgetrpc(c, -1) == nil)
 		return -1;
+	flog("convneedkey returning");
 	return 0;
 }
 
@@ -242,6 +259,7 @@ convbadkey(Conv *c, Key *k, char *msg, Attr *a)
 {
 	if(convgetrpc(c, -1) == nil)
 		return -1;
+	flog("convbadkey %A %N / %s / %A", k->attr, k->privattr, msg, a);
 	rpcrespond(c, "badkey %A %N\n%s\n%A",
 		k->attr, k->privattr, msg, a);
 	if(convgetrpc(c, -1) == nil)
diff --git a/src/cmd/auth/factotum/ctl.c b/src/cmd/auth/factotum/ctl.c
index 6195bb84..d12fbca7 100644
--- a/src/cmd/auth/factotum/ctl.c
+++ b/src/cmd/auth/factotum/ctl.c
@@ -98,12 +98,14 @@ ctlwrite(char *a)
 				l = &(*l)->next;
 		}
 		*lpriv = nil;
+		flog("addkey %A %A %N", protos, attr, priv);
 
 		/* add keys */
 		ret = 0;
 		for(pa=protos; pa; pa=pa->next){
 			if((proto = protolookup(pa->val)) == nil){
 				werrstr("unknown proto %s", pa->val);
+				flog("addkey: %r");
 				ret = -1;
 				continue;
 			}
@@ -112,6 +114,7 @@ ctlwrite(char *a)
 				if(!matchattr(kpa, attr, priv)){
 					freeattr(kpa);
 					werrstr("missing attributes -- want %s", proto->keyprompt);
+					flog("addkey %s: %r", proto->name);
 					ret = -1;
 					continue;
 				}
@@ -123,10 +126,12 @@ ctlwrite(char *a)
 			k->ref = 1;
 			k->proto = proto;
 			if(proto->checkkey && (*proto->checkkey)(k) < 0){
+				flog("addkey %s: %r", proto->name);
 				ret = -1;
 				keyclose(k);
 				continue;
 			}
+			flog("adding key: %A %N", k->attr, k->privattr);
 			keyadd(k);
 			keyclose(k);
 		}
@@ -137,6 +142,7 @@ ctlwrite(char *a)
 	case 1:	/* delkey */
 		nmatch = 0;
 		attr = parseattr(p);
+		flog("delkey %A", attr);
 		for(pa=attr; pa; pa=pa->next){
 			if(pa->type != AttrQuery && pa->name[0]=='!'){
 				werrstr("only !private? patterns are allowed for private fields");
@@ -147,6 +153,7 @@ ctlwrite(char *a)
 		for(i=0; i<ring.nkey; ){
 			if(matchattr(attr, ring.key[i]->attr, ring.key[i]->privattr)){
 				nmatch++;
+				flog("deleting %A %N", ring.key[i]->attr, ring.key[i]->privattr);
 				keyclose(ring.key[i]);
 				ring.nkey--;
 				memmove(&ring.key[i], &ring.key[i+1], (ring.nkey-i)*sizeof(ring.key[0]));
@@ -161,6 +168,7 @@ ctlwrite(char *a)
 		return 0;
 	case 2:	/* debug */
 		debug ^= 1;
+		flog("debug = %d", debug);
 		return 0;
 	}
 }
diff --git a/src/cmd/auth/factotum/fs.c b/src/cmd/auth/factotum/fs.c
index 08894ae6..2edbc7b1 100644
--- a/src/cmd/auth/factotum/fs.c
+++ b/src/cmd/auth/factotum/fs.c
@@ -372,6 +372,7 @@ fswrite(Req *r)
 	int ret;
 	char err[ERRMAX], *s;
 	int (*strfn)(char*);
+	char *name;
 
 	switch((int)r->fid->qid.path){
 	default:
@@ -387,12 +388,15 @@ fswrite(Req *r)
 		}
 		break;
 	case Qneedkey:
+		name = "needkey";
 		strfn = needkeywrite;
 		goto string;
 	case Qctl:
+		name = "ctl";
 		strfn = ctlwrite;
 		goto string;
 	case Qconfirm:
+		name = "confirm";
 		strfn = confirmwrite;
 	string:
 		s = emalloc(r->ifcall.count+1);
@@ -403,6 +407,7 @@ fswrite(Req *r)
 		if(ret < 0){
 			rerrstr(err, sizeof err);
 			respond(r, err);
+			flog("write %s: %s", name, err);
 		}else{
 			r->ofcall.count = r->ifcall.count;
 			respond(r, nil);
diff --git a/src/cmd/auth/factotum/key.c b/src/cmd/auth/factotum/key.c
index e2299b84..9df50eb3 100644
--- a/src/cmd/auth/factotum/key.c
+++ b/src/cmd/auth/factotum/key.c
@@ -67,6 +67,7 @@ keyfetch(Conv *c, char *fmt, ...)
 	a = parseattrfmtv(fmt, arg);
 	va_end(arg);
 
+	flog("keyfetch %A", a);
 	tag = 0;
 
 	for(i=0; i<ring.nkey; i++){
@@ -80,6 +81,7 @@ keyfetch(Conv *c, char *fmt, ...)
 				continue;
 			}
 			freeattr(a);
+			flog("using key %A %N", k->attr, k->privattr);
 			return k;
 		}
 	}
diff --git a/src/cmd/auth/factotum/log.c b/src/cmd/auth/factotum/log.c
index 239dca51..4d29536b 100644
--- a/src/cmd/auth/factotum/log.c
+++ b/src/cmd/auth/factotum/log.c
@@ -84,7 +84,7 @@ lbvappend(Logbuf *lb, char *fmt, va_list arg)
 {
 	char *s;
 
-	s = smprint(fmt, arg);
+	s = vsmprint(fmt, arg);
 	if(s == nil)
 		sysfatal("out of memory");
 	if(lb->msg[lb->wp])
diff --git a/src/cmd/auth/factotum/p9sk1.c b/src/cmd/auth/factotum/p9sk1.c
index 46156939..0a79a361 100644
--- a/src/cmd/auth/factotum/p9sk1.c
+++ b/src/cmd/auth/factotum/p9sk1.c
@@ -139,11 +139,14 @@ p9skclient(Conv *c)
 
 	/* success */
 	c->attr = addcap(c->attr, c->sysuser, &t);
+	flog("p9skclient success %A", c->attr);	/* before adding secret! */
 	des56to64((uchar*)t.key, secret);
 	c->attr = addattr(c->attr, "secret=%.8H", secret);
 	ret = 0;
 
 out:
+	if(ret < 0)
+		flog("p9skclient: %r");
 	freeattr(a);
 	keyclose(k);
 	return ret;
@@ -214,11 +217,14 @@ p9skserver(Conv *c)
 
 	/* success */
 	c->attr = addcap(c->attr, c->sysuser, &t);
+	flog("p9skserver success %A", c->attr);	/* before adding secret! */
 	des56to64((uchar*)t.key, secret);
 	c->attr = addattr(c->attr, "secret=%.8H", secret);
 	ret = 0;
 
 out:
+	if(ret < 0)
+		flog("p9skserver: %r");
 	freeattr(a);
 	keyclose(k);
 	return ret;
diff --git a/src/cmd/auth/factotum/secstore.c b/src/cmd/auth/factotum/secstore.c
index 315de0eb..c9009ee2 100644
--- a/src/cmd/auth/factotum/secstore.c
+++ b/src/cmd/auth/factotum/secstore.c
@@ -48,14 +48,17 @@ havesecstore(void)
 	if(fd < 0){
 		if(debug)
 			fprint(2, "secdial: %r\n");
+		flog("secdial: %r");
 		return 0;
 	}
 	if(write(fd, buf, n) != n || readn(fd, buf, 2) != 2){
+		flog("secstore: no count");
 		close(fd);
 		return 0;
 	}
 	n = ((buf[0]&0x7f)<<8) + buf[1];
 	if(n+1 > sizeof buf){
+		flog("secstore: bad count");
 		werrstr("implausibly large count %d", n);
 		close(fd);
 		return 0;
@@ -63,16 +66,23 @@ havesecstore(void)
 	m = readn(fd, buf, n);
 	close(fd);
 	if(m != n){
+		flog("secstore: unexpected eof");
 		if(m >= 0)
 			werrstr("short read from secstore");
 		return 0;
 	}
 	buf[n] = 0;
 	if(strcmp((char*)buf, "!account expired") == 0){
+		flog("secstore: account expired");
 		werrstr("account expired");
 		return 0;
 	}
-	return strcmp((char*)buf, "!account exists") == 0;
+	if(strcmp((char*)buf, "!account exists") == 0){
+		flog("secstore: account exists");
+		return 1;
+	}
+	flog("secstore: %s", buf);
+	return 0;
 }
 
 /* delimited, authenticated, encrypted connection */
@@ -384,8 +394,10 @@ getfile(SConn *conn, uchar *key, int nkey)
 		if(q = strchr(p, '\n'))
 			*q++ = '\0';
 		n++;
-		if(ctlwrite(p) < 0)
+		if(ctlwrite(p) < 0){
+			flog("secstore %s:%d: %r", gf, n);
 			fprint(2, "secstore(%s) line %d: %r\n", gf, n);
+		}
 		p = q;
 	}
 	free(buf);
@@ -636,6 +648,8 @@ secstorefetch(void)
 	rv = 0;
 
 Out:
+	if(rv < 0)
+		flog("secstorefetch: %r");
 	if(conn)
 		conn->free(conn);
 	if(pass)