d3d.py: implement status parser

TODO: .analyse() the status, try to identify failure modes and respond.
TODO: implement restart_irena()

d3d.py

@@ -1,9 +1,184 @@
 #! /usr/bin/python3
-import os, sys, os.path, time
+import os, sys, os.path, time, math
 os.chdir(os.path.dirname(sys.argv[0]))
 os.system("screen ./d3d.rc")
-wd = open("d3d/irena-live", "w")
+
+class watchdog:
+    period = 60
+
+    def __init__(self):
+        self.wd = open("d3d/irena-live", "w")
+        self.time = time.time() + self.period
+
+    def due(self):
+        return time.time() >= self.time
+
+    def kick(self):
+        self.wd.write(".");
+        self.wd.flush()
+        self.time += self.period
+
+dog = watchdog()
+
+from led import LED
+Rate_LED = LED("/var/run/gpio/Rate_LED")
+Error_LED = LED("/var/run/gpio/Error_LED")
+
+class parse_status:
+
+    "parse the lines of the `irena-status` file"
+
+    verbosity = 1
+
+    def __init__(self, lines):
+        self.hosttime = time.time()
+        self.parse(lines)
+
+    def parse(self, lines):
+        rates = False
+        self.states = {}
+        self.rates = {}
+        for l in lines:
+            ll = l.split()
+            if ll[0]=="irena":
+                self.version = ll[2]
+                self.time=int(ll[4])
+                fhosttime = time.strftime("%Y-%m-%dT%H:%M:%SZ", time.gmtime(self.hosttime))
+                if verbosity >= 1:
+                    print(f"Host time {fhosttime}, Status time {ll[5]}")
+            if ll[0]=="data":
+                rates = True
+            if not l[0].isdigit():
+                continue
+            if not rates:
+                self.rates[ll[1]] = parse_state(ll)
+            else:
+                self.rate[ll[1]] = parse_rate(ll)
+
+    max_age = 300
+
+    def old(self):
+        return self.time + self.max_age < self.hosttime
+
+    def analyse(self):
+        "Try to identify failure modes and lauch mitigations"
+        pass
+
+    def set_Rate(self, LED):
+        "Set the green LED frequency based on trigger rate"
+        r = self["T_rate"].value.percent()
+        r = max(0, min(100, r))
+        f = log(r+1)/log(100)*4+0.1
+        LED.sine_freq(f)
+
+    def set_ERROR(self, LED):
+        "Set the yellow LED based on warning or error status counts"
+        ne = 0
+        nw = 0
+        for s in self.status:
+            if not s.is_ok():
+                if s.is_warn():
+                    nw += 1
+                else:
+                    ne += 1
+        if ne:
+            LED.blink_freq(10 - min(ne,19)/2)
+        elif nw:
+            LED.on(amp = 20*min(5,nw))
+        else:
+            LED.off()
+
+class parse_state:
+    def __init__(self, ll):
+        self.ix      = int(ll[0])
+        self.name        = ll[1]
+        self.value = float(ll[2])
+        self.mean  = float(ll[3])
+        self.units       = ll[4]
+        self.age    = int(ll[5])
+        self.status     = ll[6]
+        self.reset  = int(ll[7])
+        self.limits = list(map(float, ll[8:]))
+        if !self.is_ok() and verbosity>=1:
+            print(self)
+
+    def is_ok(self):
+        return self.status == "OK"
+
+    def is_warn(self):
+        return self.status == "WARN"
+
+    def is_error(self):
+        return self.status == "ERROR"
+
+    def percent(self):
+        return 100*(self.value - self.limits[1])/(self.limits[2]-self.limits[1])
+
+    def __str__(self):
+        return " ".join([f"{self.name}:",
+                         f"{self.mean} {self.units}",
+                         f"{self.status}",
+                         f"{self.percent():.1f} %",
+                         ])
+
+class parse_rate:
+
+    def __init__(self, ll):
+        self.ix                = int(ll[0])
+        self.name                  = ll[1]
+        self.alloc_per_sec     = int(ll[2])
+        self.alloc_bytes       = int(ll[3])
+        self.used_percent    = float(ll[4])
+        self.used_bytes        = int(ll[5])
+        self.dropped_percent = float(ll[6])
+        self.dropped_bytes     = int(ll[7])
+        self.burst             = int(ll[8])
+
+    def __str__(self):
+        return " ".join([f"{self.name}:",
+                         f"{self.alloc_per_sec}/s,",
+                         f"used: {self.used_percent:.1f} %,",
+                         f"dropped: {self.dropped_percent:.1f} %",
+                         ])
+
+def restart_irena():
+    pass
+
+last_status = 0
+
 while True:
-    wd.write(".");
+
-    wd.flush()
+    t = time.time()
-    time.sleep(10)
+    t0 = t+10
+    t1 = Rate_LED.update()
+    t2 = Rate_LED.update()
+    dt = t-min(t1,t2,t3)
+    if dt>0:
+        time.sleep(dt)
+
+    if t > last_status + 10:
+        try:
+            with open("d3d/irena-status") as st:
+                status=parse_status(st.readlines(hint=0x2000))
+        except Exception as e:
+            if verbosity >= 0:
+                print(repr(e))
+            continue
+
+    if last_status != status.time:
+        status.analyse()
+        status.set_Rate(Rate_LED)
+        status.set_Error(Error_LED)
+
+    last_status = status.time
+
+    if not dog.due():
+        continue
+
+    if status.old():
+        restart_irena()
+        if verbosity >= 0:
+            print(f"not kicking the dog because status is {status.hosttime - status.time} s old")
+        continue
+
+    dog.kick()

irena.c

@@ -28,37 +28,71 @@ const char version[] = IRENA_VERSION;
 #include <sys/socket.h>
 #include <sys/un.h>
 #include <netinet/in.h>
+#include <stdarg.h>
 
 FILE *mout;
 
 int maintainance = 0;
 int verbosity[2] = {1,1};
 int in_prompt;
+const char *prompt;
 
 void check_prompt()
 {
 	if (in_prompt==1) {
-		fprintf(mout, "\n");
+		fprintf(stderr, "\r\e[K");
 		in_prompt = 2;
 	}
 }
 
+void restore_prompt()
+{
+	if (in_prompt != 2)
+		return;
+	in_prompt = 1;
+	// int nread;
+	// TIOCINQ/FIONREAD returns what is available to read immediately,
+	// not the contents of the incomplete line. Not usefull!
+	// Inject a CR, read the line, reinject all those characters?
+	// if (ioctl(0, TIOCINQ, &nread))
+		// do not call merror()!
+	//	return;
+	if (prompt) {
+		fprintf(stderr, "%s…(^R)…", prompt);
+		fflush(stderr);
+	}
+	if (0) {
+		char rprnt = 'R' & 0x1f;
+		ioctl(0, TIOCSTI, &rprnt);
+	}
+}
+
 static inline void silent(int v) { if (verbosity[0] < v) verbosity[1] = 0; }
 static inline void unsilent() { verbosity[1] = verbosity[0]; }
 static inline void loud(int v) { if (v > verbosity[0]) verbosity[1] = v; }
 static inline int verbose(int v) { v = verbosity[1] >= v; unsilent(); if (v) check_prompt(); return v; }
+static inline void unverbose() { restore_prompt(); }
+
+int mprintf(int v, const char *restrict format, ...)
+{
+	if (!verbose(v)) return 0;
+	va_list ap;
+	va_start (ap, format);
+	int r = vfprintf(mout, format, ap);
+	unverbose();
+	return r;
+}
 
 // replacement for perror()
 void merror(const char *s)
 {
 	int e = errno;
-	if (verbose(-1))
+	mprintf(-1, "%s: %s\n", s, strerror(e));
-		fprintf(mout, "%s: %s\n", s, strerror(e));
 }
 
 #define DEBUG 3
 #ifdef DEBUG
-# define debug(fmt, ...) if (verbose(DEBUG)) fprintf(mout, fmt, __VA_ARGS__)
+# define debug(fmt, ...) mprintf(DEBUG, fmt, __VA_ARGS__)
 #else
 # define debug(fmt, ...) 
 #endif
@@ -207,13 +241,10 @@ void file_close(struct file_format *ff)
 			if (rename(ff->filename, fn))
 				merror(ff->filename);
 		}
-		if (verbose(2))
+		mprintf(2, "closed and renamed «%s» to «%s»\n",  ff->filename, fn);
-			fprintf(mout, "closed and renamed «%s» to «%s»\n",  ff->filename, fn);
-	}
-	else {
-		if (verbose(2))
-			fprintf(mout, "closed file «%s»\n",  ff->filename);
 	}
+	else
+		mprintf(2, "closed file «%s»\n",  ff->filename);
 }
 
 void file_open(struct file_format *ff, time_t t)
@@ -236,7 +267,7 @@ void file_open(struct file_format *ff, time_t t)
 	}
 	if (!strcmp(ff->filename, "stderr")) {
 		if (!(ff->flags & FILE_STDIO)) {
-			fprintf(mout, "cannot use write() on «stderr»\n");
+			mprintf(-1, "cannot use write() on «stderr»\n");
 			ff->flags |= FILE_ERROR;
 			return;
 		}
@@ -248,9 +279,7 @@ void file_open(struct file_format *ff, time_t t)
 		char *mode = ff->flags&FILE_APPEND ? "a" : "w";
 		ff->f = fopen(ff->filename, mode);
 		if (ff->f) {
-			if (verbose(2))
+			mprintf(2, "fopen(%s, %s)\n", ff->filename, mode);
-				fprintf(mout, "fopen(%s, %s)\n",
-					ff->filename, mode);
 			return;
 		}
 	}
@@ -260,8 +289,7 @@ void file_open(struct file_format *ff, time_t t)
 			f = O_CREAT|O_WRONLY|O_TRUNC;
 		ff->fd = open(ff->filename, f, 0664);
 		if (ff->fd>=0) {
-			if (verbose(2))
+			mprintf(2, "open(%s)\n", ff->filename);
-				fprintf(mout, "open(%s)\n", ff->filename);
 			return;
 		}
 	}
@@ -300,7 +328,7 @@ int config_file(struct file_format *f, int na, char **av)
 	int do_close = 0;
 	int do_open = 0;
 	if (na<1 || na>5) {
-		fprintf(mout,
+		mprintf(-2,
 			"usage: %s [«strftime» [«rotate» [«modulus» [«flags»]]]] [close|rotate]\n"
 			"- «strftime»: filename strftime format | stdout | stderr\n"
 			"- «rotate»: rotation interval, seconds (-1 for no change)\n"
@@ -342,7 +370,7 @@ int config_file(struct file_format *f, int na, char **av)
 			if (flags & FILE_STDOUT) fnf = "stdout";
 		}
 		if (strlen(fnf) > MAX_FN-2) {
-			fprintf(mout, "filename format too long (>%d): %s\n", MAX_FN-2, fnf);
+			mprintf(-2, "filename format too long (>%d): %s\n", MAX_FN-2, fnf);
 			return -1;
 		}
 		strncpy(f->format, fnf, MAX_FN-1);
@@ -354,7 +382,7 @@ int config_file(struct file_format *f, int na, char **av)
 	else if (do_open)
 		file_open(f, 0);
 	int io = is_open(f);
-	fprintf(mout, "%s '%s' %d %d 0x%x  '%s'\n",
+	mprintf(-2, "%s '%s' %d %d 0x%x  '%s'\n",
 		av[0], f->format, f->rotate, f->rotate_modulus, f->flags,
 		io ? f->filename : "CLOSED");
 	return io;
@@ -582,7 +610,7 @@ int config_priority(int na, char **av)
 		na--;
 	}
 	if (na<2 || na>6) {
-		fprintf(mout,
+		mprintf(-2,
 			"usage: %s [«index» [«rate» [«inst» [«burst» [«flags»]]]]] [global] [reset]\n"
 			"- configure data rate limits\n"
 			"- «index»: 0…%d: table index\n"
@@ -604,7 +632,7 @@ int config_priority(int na, char **av)
 	       ||          number(av[1], &index))
 		return -1;
 	if (index<0 || index>=NPRIO) {
-		fprintf(mout, "rate index %d out of range 0…%d\n",
+		mprintf(-2, "rate index %d out of range 0…%d\n",
 			index, NPRIO-1);
 		return -1;
 	}
@@ -614,7 +642,7 @@ int config_priority(int na, char **av)
 	if (burst >= 0) ep->inst_burst = burst;
 	if (flags != -1) ep->flags = flags;
 	flags |= fflags;
-	fprintf(mout, "%s: %s %u %u %u %u 0x%x -> %llu(%llu)/%llu %u/%u\n",
+	mprintf(-2, "%s: %s %u %u %u %u 0x%x -> %llu(%llu)/%llu %u/%u\n",
 		ep->name, av[0], index, ep->rate, ep->inst_rate, ep->inst_burst, ep->flags,
 		ep->sent, ep->dropped, ep->allowed, ep->inst_sent, ep->inst_burst);
 	if (do_reset)
@@ -950,7 +978,7 @@ void print_status(FILE *f, time_t t)
 					did_reset = 1;
 				tried_reset = 1;
 				if (did_reset) {
-					fprintf(mout, "IRENA ARM RESET SENT %s = %-.*f exceeds (%g, %g)\n",
+					mprintf(-2, "IRENA ARM RESET SENT %s = %-.*f exceeds (%g, %g)\n",
 						st->name, st->digits, mean, st->limits[0], st->limits[3]);
 					st->did_reset = t;
 					last_status_reset = t;
@@ -971,11 +999,14 @@ void print_status(FILE *f, time_t t)
 int config_status(int na, char **av)
 {
 	if (na==1) {
+		if (verbose(-2)) {
 			print_status(mout, 0);
+			unverbose();
+		}
 		return 0;
 	}
 	if (na!=2 && (na<6 || na>9)) {
-		fprintf(mout,
+		mprintf(-2,
 			"usage: %s [«index» [«red» «yellow» «yellow» «red» [«tau» [«reset»] [«flags»]]]]\n"
 			"- «index»: 0…%d, table index\n"
 			"- «red»: lower/upper error limit\n"
@@ -998,7 +1029,7 @@ int config_status(int na, char **av)
 	if (number(av[1], &index))
 		return -1;
 	if (index<0 || index>=NSTAT) {
-		fprintf(mout, "limits index %d out of range 0…%d\n",
+		mprintf(-2, "limits index %d out of range 0…%d\n",
 			index, NSTAT-1);
 		return -1;
 	}
@@ -1027,7 +1058,7 @@ int config_status(int na, char **av)
 			else
 				st->flags |= ST_DO_RESET;
 		else
-			fprintf(mout, "%s … «reset» = reset | noreset | «seconds»\n", av[0]);
+			mprintf(-2, "%s … «reset» = reset | noreset | «seconds»\n", av[0]);
 	if (na>=9) {
 		int f;
 		if (!number(av[8], &f)) {
@@ -1036,7 +1067,7 @@ int config_status(int na, char **av)
 		}
 	}
 		
-	fprintf(mout, "%s %s[%u] %g %g %g %g %s tau %d reset %d flags 0x%04x\n",
+	mprintf(-2, "%s %s[%u] %g %g %g %g %s tau %d reset %d flags 0x%04x\n",
 		av[0], st->name, index,
 		st->limits[0], st->limits[1], st->limits[2], st->limits[3],
 		st->units, st->tau, st->reset_delay, st->flags);
@@ -1197,8 +1228,7 @@ int arm_reset()
 		arm_reset_uart(i_buf.fd, reset_flags);
 	else
 		return -1;
-	if (verbose(0))
+	mprintf(0, "Sent hardware RESET, mode %d\n", reset_flags);
-		fprintf(mout, "Sent hardware RESET, mode %d\n", reset_flags);
 	return 0;
 }
 
@@ -1282,18 +1312,18 @@ int test_serial_read_buffer(int na, char **av)
 {
 	int s = 1;
 	if (na>=2 && number(av[1], &s)) {
-		fprintf(mout, "usage: %s [«seconds»]\n", av[0]);
+		mprintf(-2, "usage: %s [«seconds»]\n", av[0]);
 		return -1;
 	}
 	if (i_buf.fd<0) {
+		mprintf(-2, "uart is closed\n");
 		return -1;
-		fprintf(mout, "uart is closed\n");
 	}
 	buffer_reset(&i_buf);
 	sleep(s);
 	char buf[65536];
 	int n = read(i_buf.fd, &buf, sizeof(buf)-1);
-	fprintf(mout, "uart read buffer size >= %d\n", n);
+	mprintf(-2, "uart read buffer size >= %d\n", n);
 	return n;
 }
 
@@ -1328,8 +1358,7 @@ int base64_decode(const char *l, unsigned char *b, size_t n)
 			else if (!i && (!c || c=='\n'))
 				return m;
 			else if (c&0x80 || !bb[i] && c!='A') {
-				if (verbose(0))
+				mprintf(0, "Base64 format error: %s\n", l);
-					fprintf(mout, "Base64 format error: %s\n", l);
 				return 0;
 			}
 		}
@@ -1394,8 +1423,8 @@ int base85_decode(const char *l, unsigned char *b, size_t n)
 			l++;
 		int ll = base85_decode1(l, (unsigned int*)(b+m));
 		if (!ll) {
-			if (*l && verbose(0))
+			if (*l)
-				fprintf(mout, "invalid base85: «%s»\n", l);
+				mprintf(0, "invalid base85: «%s»\n", l);
 			return m;
 		}
 		l += ll;
@@ -2158,23 +2187,21 @@ int send_irena_command(const char *c)
 {
 	static int no_uart;
 	if (i_buf.fd <= 0) {
-		if (!no_uart && verbose(-1))
+		if (!no_uart)
-			fprintf(mout, "irena: no uart: %s\n", c);
+			mprintf(-1, "irena: no uart: %s\n", c);
 		no_uart++;
 		return -1;
 	}
 	no_uart=0;
 	time_t t = time(0);
 	if (last_irena_command_sent+1 >= t) {
-		if (verbose(3))
+		mprintf(3, "IRENA CMD postponed: %s\n", c);
-			fprintf(mout, "IRENA CMD postponed: %s\n", c);
 		return -2;
 	}
 	size_t sl = strlen(c);
 	int n = write(i_buf.fd, c, sl);
 	last_irena_command_sent = t;
-	if (verbose(2))
+	mprintf(2, "IRENA CMD sent: «%s»\n", c);
-		fprintf(mout, "IRENA CMD sent: «%s»\n", c);
 	if (n==sl)
 		n += write(i_buf.fd, "\n", 1);
 	if (n != sl+1)
@@ -2183,8 +2210,7 @@ int send_irena_command(const char *c)
 			return -3;
 		}
 		else {
-			if (verbose(-1))
+			mprintf(-1, "incomplete write: %d/%lu %s\n", n, strlen(c), c);
-				fprintf(mout, "incomplete write: %d/%lu %s\n", n, strlen(c), c);
 			return -4;
 		}
 	return 0;
@@ -2235,6 +2261,8 @@ void send_fct(time_t t)
 void process_line(const char *l)
 {
 	// ack a sent command when we see the response
+	if (!*l)
+		return;
 	if (*l=='.' || *l=='m')
 		last_irena_command_sent = 0;
 	int fmt = 0;
@@ -2243,19 +2271,16 @@ void process_line(const char *l)
 	if (fmt) {
 		fct_got_data++;
 		fct_packets++;
-		if (verbose(3))
+		mprintf(3, "DATA received: «%s»\n", l);
-			fprintf(mout, "DATA received: «%s»\n", l);
 		process_base64(fmt, l+5);
 		return;
 	}
 	if (*l && !strncmp(l+1, "FCT ", 4)) {
 		fct_ack++;
-		if (verbose(4))
+		mprintf(4, "FCT ACK received %d, «%s»\n", fct_ack, l);
-			fprintf(mout, "FCT ACK received %d, «%s»\n", fct_ack, l);
 		return;
 	}
-	if (verbose(1))
+	mprintf(1, "IRENA: %s\n", l);
-		fprintf(mout, "IRENA: %s\n", l);
 	eprintf(EP_M, "I %s\n", l);
 }
 
@@ -2331,14 +2356,12 @@ int send_file(const char *fn, const char *cfmt, unsigned int drop)
 			continue;
 		}
 		if (i >= 2) {
-			if (verbose(-1))
+			mprintf(-1, "more than two in parameters «%s»\n", cfmt);
-				fprintf(mout, "more than two in parameters «%s»\n", cfmt);
 			return -3;
 		}
 		while (index(".-+#0123456789", *s)) s++;
 		if (!*s || !index("diuoOxX", *s)) {
-			if (verbose(-1))
+			mprintf(-1, "invalid format «%s»\n", cfmt);
-				fprintf(mout, "invalid format «%s»\n", cfmt);
 			return -3;
 		}
 		i++;
@@ -2360,8 +2383,7 @@ int send_file(const char *fn, const char *cfmt, unsigned int drop)
 		int d = 1;
 		if (drop) while (d<128 && buf[d]==buf[0]) d++;
 		if (d>=128 && buf[0]==0xffffffff) {
-			if (verbose(2))
+			mprintf(2, "dropping block %d\n", a/128);
-				fprintf(mout, "dropping block %d\n", a/128);
 			continue;
 		}
 		for (int i=0; i<128; ) {
@@ -2376,9 +2398,9 @@ int send_file(const char *fn, const char *cfmt, unsigned int drop)
 					poll_uart(1);
 				char *res = poll_response(2);
 				if (!res)
-					fprintf(mout, "timeout for cmd «%s»\n", cmd);
+					mprintf(-2, "timeout for cmd «%s»\n", cmd);
 				else if (strncmp(res+1, "303", 3))
-					fprintf(mout, "invalid response to «%s» → «%s»\n", cmd, res);
+					mprintf(-2, "invalid response to «%s» → «%s»\n", cmd, res);
 				else
 					break;
 				poll_uart(0);
@@ -2392,8 +2414,8 @@ int send_file(const char *fn, const char *cfmt, unsigned int drop)
 			int cs = snprintf(cmd, 128, cfmt, a, n);
 			if (cs <= 127)
 				process_cmd(cmd);
-			else if (verbose(-1))
+			else
-				fprintf(mout, "sendfile format too long «%s»\n", cmd);
+				mprintf(-1, "sendfile format too long «%s»\n", cmd);
 		}
 		do_cron(0, CR_BUFFER, 1);
 		a += n;
@@ -2417,8 +2439,7 @@ int set_clock(int do_sleep)
 		while (ts.tv_nsec < 900000000) {
 			ts.tv_nsec += 50000000;
 			clock_nanosleep(CLOCK_REALTIME, TIMER_ABSTIME, &ts, 0);
-			if (verbose(3))
+			mprintf(3, "slept 50ms ns=%lu\n", ts.tv_nsec);
-				fprintf(mout, "slept 50ms ns=%lu\n", ts.tv_nsec);
 			poll_uart(1);
 			clock_gettime(CLOCK_REALTIME, &ts);
 		}
@@ -2495,8 +2516,7 @@ const char *cmd_socket_name() {
 int close_cmd_socket()
 {
 	if (cmd_socket_fd >= 0) {
-		if (verbose(1))
+		mprintf(1, "closing cmd socket: «%s»\n", cmd_socket_name());
-			fprintf(mout, "closing cmd socket: «%s»\n", cmd_socket_name());
 		epoll_ctl(epoll_fd, EPOLL_CTL_DEL, cmd_socket_fd, 0);
 		close(cmd_socket_fd);
 		cmd_socket_fd = -1;
@@ -2566,17 +2586,20 @@ int open_cmd_socket(int na, char **av)
 		cmd_socket_addr.u.sun_family = AF_UNIX;
 		strncpy(cmd_socket_addr.u.sun_path, av[na-1], sizeof(cmd_socket_addr.u.sun_path)-1);
 		if (force && !unlink(cmd_socket_addr.u.sun_path))
-		    fprintf(mout, "socket «%s» unlinked\n", cmd_socket_addr.u.sun_path);
+		    mprintf(-2, "socket «%s» unlinked\n", cmd_socket_addr.u.sun_path);
 	}
 	else if (na==1) {
 	is_open:
+		if (verbose(-1)) {
 			fprintf(mout, "command socket is %s«%s»\n", mode, cmd_socket_name());
 			print_asocket(mout);
+			unverbose();
+		}
 		return 0;
 	}
 	else {
 	usage:
-		fprintf(mout,
+		mprintf(-2,
 			"usage: %s [unix «path» | tcp «port»]"
 			" [interactive|noninteractive] [close]\n", av[0]);
 		return -1;
@@ -2608,7 +2631,7 @@ int open_cmd_socket(int na, char **av)
 		return -1;
 	}
 
-	fprintf(mout, "opened %ssocket «%s»\n", mode, cmd_socket_name());
+	mprintf(-2, "opened %ssocket «%s»\n", mode, cmd_socket_name());
 	return 0;
 }
 
@@ -2624,7 +2647,7 @@ int accept_cmd_socket(int fd)
 	}
 		
 	if (s_buf.fd >= 0) {
-		fprintf(mout, "command socket busy\n");
+		mprintf(-2, "command socket busy\n");
 		close(sfd);
 		return -1;
 	}
@@ -2652,11 +2675,13 @@ int accept_cmd_socket(int fd)
 			return sfd;
 		}
 		cmd_socket_flags |= SOCK_IS_MOUT;
-		fprintf(mout, "irena %s\n", version);
+		mprintf(-2, "irena %s\n", version);
 	}
 
-	if (verbose(0))
+	if (verbose(0)) {
 		print_asocket(stderr);
+		unverbose();
+	}
 
 	return sfd;
 }
@@ -2675,6 +2700,7 @@ int close_acmd_socket()
 	if (verbose(0)) {
 		print_asocket(stderr);
 		fprintf(stderr, "closing socket connection\n");
+		unverbose();
 	}
 	if (s_buf.fd >= 0) {
 		if (epoll_ctl(epoll_fd, EPOLL_CTL_DEL, s_buf.fd, 0))
@@ -2694,7 +2720,7 @@ int number(char *s, int *i)
 	char *e;
 	int ii = strtol(s, &e, 0);
 	if (*e) {
-		fprintf(mout, "invalid number: %s\n", s);
+		mprintf(-2, "invalid number: %s\n", s);
 		return -1;
 	}
 	*i = ii;
@@ -2707,7 +2733,7 @@ int index_number(char *s, int *i)
 	char *e;
 	int ii = strtol(s+1, &e, 0);
 	if (*e != ']') {
-		fprintf(mout, "invalid index: %s\n", s);
+		mprintf(-2, "invalid index: %s\n", s);
 		return -1;
 	}
 	*i = ii;
@@ -2719,7 +2745,7 @@ int float_number(char *s, double *d)
 	char *e;
 	double dd = strtod(s, &e);
 	if (*e) {
-		fprintf(mout, "invalid float number: %s\n", s);
+		mprintf(-2, "invalid float number: %s\n", s);
 		return -1;
 	}
 	*d = dd;
@@ -2828,7 +2854,7 @@ int process_script(const char *fn)
 {
 	static int recursion = 0;
 	if (recursion>10) {
-		fprintf(mout, "script: «%s»: nested too deep, limit 10\n", fn);
+		mprintf(-2, "script: «%s»: nested too deep, limit 10\n", fn);
 		return -2;
 	}
 
@@ -2842,7 +2868,7 @@ int process_script(const char *fn)
 	char cmd[128];
 	while (fgets(cmd, sizeof(cmd), f)) {
 		if (!index(cmd, '\n')) {
-			fprintf(mout, "script: unterminated or long line: «%s»\n", cmd);
+			mprintf(-2, "script: unterminated or long line: «%s»\n", cmd);
 			break;
 		}
 		process_cmd(cmd);
@@ -2863,26 +2889,27 @@ int process_cmd(char *l)
 	int na = split(l, 10, av);
 	if (!na || av[0][0]=='#')
 		return 0;
-	check_prompt();
+	if (verbose(2) || !strcmp(av[0], "echo") && verbose(-2)) {
-	if (verbose(2) || !strcmp(av[0], "echo")) {
 		fprintf(mout, "CMD:");
 		for (int i=0; i<na; i++)
 			fprintf(mout, " «%s»", av[i]);
 		fprintf(mout, "\n");
+		unverbose();
 	}
 	if (!strcmp(av[0], "echo")) {
 		return 0;
 	}
 
 	if (!strcmp(av[0], "version")) {
-		fprintf(mout, "irena version %s\n", version);
+		mprintf(-2, "irena version %s\n", version);
 		return 0;
 	}
 
 	int help = na>=2 && !strcmp(av[1], "help");
 
 	if (!strcmp(av[0], "help")) {
-		fprintf(mout, "available commands\n"
+		if (!verbose(-2)) return 0;
+		mprintf(-2, "available commands\n"
 			"commands:\n"
 			"\thelp\n"
 			"\tversion\n"
@@ -2911,10 +2938,13 @@ int process_cmd(char *l)
 			"\n"
 			);
 		print_numbers(mout);
+		unverbose();
 		return 0;
 	}
 	if (!strcmp(av[0], "numbers")) {
+		if (!verbose(-2)) return 0;
 		print_numbers(mout);
+		unverbose();
 		return 0;
 	}
 
@@ -2933,9 +2963,9 @@ int process_cmd(char *l)
 		}
 		if (help || ii<0 || na+ii > nn) {
 			if (nn>1) 
-				fprintf(mout, "usage: %s [[«i»]] «%s» [… %d items]\n", n->name, n->doc, nn);
+				mprintf(-2, "usage: %s [[«i»]] «%s» [… %d items]\n", n->name, n->doc, nn);
 			else
-				fprintf(mout, "usage: %s «%s»\n", n->name, n->doc);
+				mprintf(-2, "usage: %s «%s»\n", n->name, n->doc);
 			na = 0;
 		}
 
@@ -2958,14 +2988,17 @@ int process_cmd(char *l)
 			if (r)
 				return -1;
 		}
+		if (verbose(-2)) {
 			print_number(mout, n);
+			unverbose();
+		}
 		return 0;
 	}
 
 	if (!strcmp(av[0], "exit")) {
 		int code = 0;
 		if (help || na>2 || na==2 && number(av[1], &code)) {
-			fprintf(mout, "usage: exit [«status»]\n");
+			mprintf(-2, "usage: exit [«status»]\n");
 			return -1;
 		}
 		file_close(&data_file);
@@ -2978,7 +3011,7 @@ int process_cmd(char *l)
 	if (!strcmp(av[0], "sleep")) {
 		int sec;
 		if (help || na!=2 || number(av[1], &sec)) {
-			fprintf(mout, "usage: sleep «seconds»\n");
+			mprintf(-2, "usage: sleep «seconds»\n");
 			return -1;
 		}
 		sleep(sec);
@@ -2987,7 +3020,7 @@ int process_cmd(char *l)
 
 	if (!strcmp(av[0], "script")) {
 		if (help || na!=2) {
-			fprintf(mout, "usage: script «filename»\n");
+			mprintf(-2, "usage: script «filename»\n");
 			return -1;
 		}
 		return process_script(av[1]);
@@ -2998,7 +3031,7 @@ int process_cmd(char *l)
 		int drop = 0;
 		int i = 2;
 		if (help) {
-			fprintf(mout, "usage: sendfile [drop] «filename» [«command»]\n"
+			mprintf(-2, "usage: sendfile [drop] «filename» [«command»]\n"
 				"- send contents of «filename» as 512 Byte blocks into the flashbuffer,\n"
 				"- optionally, send irena «command»,\n"
 				"- execute any cron items flagged `buffer`.\n"
@@ -3036,14 +3069,14 @@ int process_cmd(char *l)
 			if (!strcmp(av[2], "1000000")) baud = B1000000;
 			if (!strcmp(av[2], "1500000")) baud = B1500000;
 			if (baud==B0) {
-				fprintf(mout, "uart: illegal baud rate: %s\n"
+				mprintf(-2, "uart: illegal baud rate: %s\n"
 					"valid: 9600, 38400, 57600, 115200, 921600, 1000000, 1500000\n"
 					"default: 921600\n", av[2]);
 				return -1;
 			}
 		}
 		if (help || na<2 || na>4 || na==4 && !do_reset) {
-			fprintf(mout,
+			mprintf(-2,
 				"usage: uart «tty» [«baudrate»] [«reset»]\n"
 				"- open the serial port,\n"
 				"- optionally reset the µC, and\n"
@@ -3064,7 +3097,7 @@ int process_cmd(char *l)
 
 	if (!strcmp(av[0], "irena") || !strcmp(av[0],"var")) {
 		if (help || na <= 1) {
-			fprintf(mout,
+			mprintf(-2,
 				"usage: irena «command»\n"
 				"usage: var «variable command»\n"
 				" (short for `irena var «command»`)\n"
@@ -3095,7 +3128,7 @@ int process_cmd(char *l)
 			if (na>3 || na>2 && !config)
 				do_sleep = -1;
 			if (help || do_sleep < 0) {
-				fprintf(mout,
+				mprintf(-2,
 					"usage: set_clock [nosleep|sleep|drift|fudge] [config]\n"
 					"- set the µC RTC to the current host time.\n"
 					"option `sleep`: Wait until the end of the current second.\n"
@@ -3145,9 +3178,14 @@ int process_cmd(char *l)
 
 	if (!strcmp(av[0], "cron")) {
 		if (help || config_cron(na, av) == -1)
-			fprintf(mout, "usage:\tcron [«index» [«flags»… [«delay» «cmd»]]]\n"
+			mprintf(-2, "usage:\tcron [«index» [«flags»… [«delay» «cmd»]]]\n"
 				"\tcron force «flags»… [«times»]\n"
-				"\tcron «index» delete\n");
+				"\tcron «index» delete\n"
+				"\t\tindex: `next`, 0 … 15\n"
+				"\t\tflags: init reset once ever buffer\n"
+				"\t\t\tgot_hk got_cntr got_bate did_let\n"
+				"\t\t\trotate_data rotate_cntr rotate_stat\n"
+				);
 		return 0;
 	}
 
@@ -3159,14 +3197,14 @@ int process_cmd(char *l)
 		for (pp=paths; pp->name; pp++) 
 			if (na<2 || !strcmp(av[1], pp->name)) {
 				if (na<3) 
-					fprintf(mout, "path %s %s\n", pp->name, *pp->path);
+					mprintf(-2, "path %s %s\n", pp->name, *pp->path);
 				else if (na==3)
 					strncpy(*pp->path, av[2], MAX_FN-1);
 				if (na>1)
 					break;
 			}
 		if (help || na>3 || na>1 && !pp->name)
-			fprintf(mout, "usage:\tpath [«name» [«value»]]\n");
+			mprintf(-2, "usage:\tpath [«name» [«value»]]\n");
 		return 0;
 	}
 
@@ -3174,7 +3212,7 @@ int process_cmd(char *l)
 		// #! /usr/bin/env ./irena
 		return process_script(av[0]);
 
-	fprintf(mout, "unknown command '%s', try help\n", av[0]);
+	mprintf(-2, "unknown command '%s', try help\n", av[0]);
 	return -1;
 }
 
@@ -3238,7 +3276,7 @@ int config_cron(int na, char **av)
 			struct cron *cr = &cron[i];
 			if (!*cr->cmd)
 				continue;
-			fprintf(mout, "%s %d 0x%04x %d (%d@%ld) «%s»\n", 
+			mprintf(-2, "%s %d 0x%04x %d (%d@%ld) «%s»\n",
 				av[0], i, cr->flags, cr->delay, cr->times, cr->when, cr->cmd);
 		}
 		return 0;
@@ -3252,7 +3290,7 @@ int config_cron(int na, char **av)
 				break;
 			}
 		if (idx<0) {
-			fprintf(mout, "no free crontab entries\n");
+			mprintf(-2, "no free crontab entries\n");
 			return -2;
 		}
 	}
@@ -3314,7 +3352,7 @@ int config_cron(int na, char **av)
 	if (idx<0) {
 		if (!flags || ai!=na)
 			return -1;
-		fprintf(mout, "forcing cron flags 0x%04x, %d times\n", flags, delay);
+		mprintf(-2, "forcing cron flags 0x%04x, %d times\n", flags, delay);
 		do_cron(0, flags, delay);
 		return 0;
 	}
@@ -3332,7 +3370,7 @@ int config_cron(int na, char **av)
 		strncpy(cr->cmd, av[ai], CRON_CMD_SIZE-1);
 	}
 
-	fprintf(mout, "%s %d 0x%04x %d (%d@%ld) «%s»\n",
+	mprintf(-2, "%s %d 0x%04x %d (%d@%ld) «%s»\n",
 		av[0], idx, cr->flags, cr->delay, cr->times, cr->when, cr->cmd);
 	return 0;
 }
@@ -3371,10 +3409,9 @@ int main(int argc, char **argv)
 	for (int i=1; i<argc && argv[i]; i++)
 		process_cmd(argv[i]);
 
-	const char *prompt = NULL;
 	if (isatty(0) && isatty(2)) {
 		prompt = "IRENA> ";
-		fprintf(mout, prompt);
+		fprintf(stderr, prompt);
 		in_prompt = 1;
 	}
 
@@ -3390,8 +3427,8 @@ int main(int argc, char **argv)
 		int n = epoll_wait(epoll_fd, eev, 2, 1000);
 		time_t t = time(0);
 		for (int i=0; i<n; i++) {
-			if (eev[i].events != EPOLLIN && verbose(2))
+			if (eev[i].events != EPOLLIN)
-				fprintf(mout, "epoll: fd=%d events=0x%x\n", eev[i].data.fd, eev[i].events);
+				mprintf(2, "epoll: fd=%d events=0x%x\n", eev[i].data.fd, eev[i].events);
 			if (eev[i].data.fd == cmd_socket_fd)
 				accept_cmd_socket(cmd_socket_fd);
 			else if (eev[i].data.fd == s_buf.fd) {
@@ -3399,7 +3436,9 @@ int main(int argc, char **argv)
 				if (!l)
 					close_acmd_socket(&s_buf);
 				while (l) {
+					in_prompt = 0;
 					process_cmd(l);
+					in_prompt = !!prompt;
 					l = get_line(&s_buf, 0);
 				}
 			}
@@ -3407,14 +3446,7 @@ int main(int argc, char **argv)
 				poll_uart(eev[i].events);
 			}
 			else {
-				int do_read = eev[i].events;
+				char *l = get_line(&c_buf, eev[i].events);
-				if (prompt && in_prompt==2 && do_read) {
-					fprintf(stderr, prompt);
-					reprint_line(stderr, &c_buf);
-					in_prompt = 1;
-					do_read = 0;
-				}
-				char *l = get_line(&c_buf, do_read);
 				while (l) {
 					in_prompt = 0;
 					process_cmd(l);
@@ -3423,6 +3455,7 @@ int main(int argc, char **argv)
 							fprintf(stderr, "M:%s", prompt);
 						else
 							fprintf(stderr, prompt);
+						if (mout==stderr)
 							in_prompt = 1;
 					}
 					l = get_line(&c_buf, 0);