Merge 63500f8dd0 into 8bf5f8873f

The extension of the timestamp size is missing in log2asc.c and canplayer.c

Fixes: 987bc8aac2 ("Optional nanosecond timestamp logging")
Signed-off-by: Oliver Hartkopp <socketcan@hartkopp.net>

candump.c

@@ -128,6 +128,7 @@ static void print_usage(void)
 	fprintf(stderr, "Options:\n");
 	fprintf(stderr, "         -t <type>   (timestamp: (a)bsolute/(d)elta/(z)ero/(A)bsolute w date)\n");
 	fprintf(stderr, "         -H          (read hardware timestamps instead of system timestamps)\n");
+	fprintf(stderr, "         -N          (log nanosecond timestamps instead of microseconds)\n");
 	fprintf(stderr, "         -c          (increment color mode level)\n");
 	fprintf(stderr, "         -i          (binary output - may exceed 80 chars/line)\n");
 	fprintf(stderr, "         -a          (enable additional ASCII output)\n");
@@ -220,16 +221,22 @@ static int idx2dindex(int ifidx, int socket)
 	return i;
 }
 
-static int sprint_timestamp(char *ts_buffer, const char timestamp,
-			    const struct timeval *tv, struct timeval *const last_tv)
+static int sprint_timestamp(char *ts_buffer, const char timestamp, const char use_ns,
+			    const struct timespec *ts, struct timespec *const last_ts)
 {
 	int numchars = 0;
 
 	switch (timestamp) {
 	case 'a': /* absolute with timestamp */
-		numchars = sprintf(ts_buffer, "(%010llu.%06llu) ",
-				   (unsigned long long)tv->tv_sec,
-				   (unsigned long long)tv->tv_usec);
+		if (use_ns) {
+			numchars = sprintf(ts_buffer, "(%010llu.%09llu) ",
+					   (unsigned long long)ts->tv_sec,
+					   (unsigned long long)ts->tv_nsec);
+		} else {
+			numchars = sprintf(ts_buffer, "(%010llu.%06llu) ",
+					   (unsigned long long)ts->tv_sec,
+					   (unsigned long long)ts->tv_nsec / 1000);
+		}
 		break;
 
 	case 'A': /* absolute with date */
@@ -237,32 +244,43 @@ static int sprint_timestamp(char *ts_buffer, const char timestamp,
 		struct tm tm;
 		char timestring[25];
 
-		tm = *localtime(&tv->tv_sec);
+		tm = *localtime(&ts->tv_sec);
 		strftime(timestring, 24, "%Y-%m-%d %H:%M:%S", &tm);
-		numchars = sprintf(ts_buffer, "(%s.%06llu) ", timestring,
-				   (unsigned long long)tv->tv_usec);
+		if (use_ns) {
+			numchars = sprintf(ts_buffer, "(%s.%09llu) ", timestring,
+					   (unsigned long long)ts->tv_nsec);
+		} else {
+			numchars = sprintf(ts_buffer, "(%s.%06llu) ", timestring,
+					   (unsigned long long)ts->tv_nsec / 1000);
+		}
 	}
 	break;
 
 	case 'd': /* delta */
 	case 'z': /* starting with zero */
 	{
-		struct timeval diff;
+		struct timespec diff;
 
-		if (last_tv->tv_sec == 0) /* first init */
-			*last_tv = *tv;
-		diff.tv_sec = tv->tv_sec - last_tv->tv_sec;
-		diff.tv_usec = tv->tv_usec - last_tv->tv_usec;
-		if (diff.tv_usec < 0)
-			diff.tv_sec--, diff.tv_usec += 1000000;
+		if (last_ts->tv_sec == 0) /* first init */
+			*last_ts = *ts;
+		diff.tv_sec = ts->tv_sec - last_ts->tv_sec;
+		diff.tv_nsec = ts->tv_nsec - last_ts->tv_nsec;
+		if (diff.tv_nsec < 0)
+			diff.tv_sec--, diff.tv_nsec += 1000000000;
 		if (diff.tv_sec < 0)
-			diff.tv_sec = diff.tv_usec = 0;
-		numchars = sprintf(ts_buffer, "(%03llu.%06llu) ",
-				   (unsigned long long)diff.tv_sec,
-				   (unsigned long long)diff.tv_usec);
+			diff.tv_sec = diff.tv_nsec = 0;
+		if (use_ns) {
+			numchars = sprintf(ts_buffer, "(%03llu.%09llu) ",
+					   (unsigned long long)diff.tv_sec,
+					   (unsigned long long)diff.tv_nsec);
+		} else {
+			numchars = sprintf(ts_buffer, "(%03llu.%06llu) ",
+					   (unsigned long long)diff.tv_sec,
+					   (unsigned long long)diff.tv_nsec / 1000);
+		}
 
 		if (timestamp == 'd')
-			*last_tv = *tv; /* update for delta calculation */
+			*last_ts = *ts; /* update for delta calculation */
 	}
 	break;
 
@@ -288,6 +306,7 @@ int main(int argc, char **argv)
 	unsigned char timestamp = 0;
 	unsigned char logtimestamp = 'a';
 	unsigned char hwtimestamp = 0;
+	unsigned char use_ns = 0;
 	unsigned char down_causes_exit = 1;
 	unsigned char dropmonitor = 0;
 	unsigned char extra_msg_info = 0;
@@ -322,7 +341,7 @@ int main(int argc, char **argv)
 	static cu_t cu; /* union for CAN CC/FD/XL frames */
 	int nbytes, i;
 	struct ifreq ifr;
-	struct timeval tv, last_tv;
+	struct timespec ts, last_ts;
 	int timeout_ms = -1; /* default to no timeout */
 	FILE *logfile = NULL;
 	char fname[83]; /* suggested by -Wformat-overflow= */
@@ -334,12 +353,12 @@ int main(int argc, char **argv)
 	signal(SIGHUP, sigterm);
 	signal(SIGINT, sigterm);
 
-	last_tv.tv_sec = 0;
-	last_tv.tv_usec = 0;
+	last_ts.tv_sec = 0;
+	last_ts.tv_nsec = 0;
 
 	progname = basename(argv[0]);
 
-	while ((opt = getopt(argc, argv, "t:HciaSs:lf:Ln:r:Dde8xT:h?")) != -1) {
+	while ((opt = getopt(argc, argv, "t:HNciaSs:lf:Ln:r:Dde8xT:h?")) != -1) {
 		switch (opt) {
 		case 't':
 			timestamp = optarg[0];
@@ -359,6 +378,10 @@ int main(int argc, char **argv)
 			hwtimestamp = 1;
 			break;
 
+		case 'N':
+			use_ns = 1;
+			break;
+
 		case 'c':
 			color++;
 			break;
@@ -784,7 +807,11 @@ int main(int argc, char **argv)
 			     cmsg && (cmsg->cmsg_level == SOL_SOCKET);
 			     cmsg = CMSG_NXTHDR(&msg,cmsg)) {
 				if (cmsg->cmsg_type == SO_TIMESTAMP) {
+					struct timeval tv;
 					memcpy(&tv, CMSG_DATA(cmsg), sizeof(tv));
+					ts.tv_sec = tv.tv_sec;
+					ts.tv_nsec = tv.tv_usec;
+					ts.tv_nsec *= 1000;
 				} else if (cmsg->cmsg_type == SO_TIMESTAMPING) {
 					struct timespec *stamp = (struct timespec *)CMSG_DATA(cmsg);
 
@@ -795,8 +822,7 @@ int main(int argc, char **argv)
 					 * See chapter 2.1.2 Receive timestamps in
 					 * linux/Documentation/networking/timestamping.txt
 					 */
-					tv.tv_sec = stamp[2].tv_sec;
-					tv.tv_usec = stamp[2].tv_nsec / 1000;
+					ts = stamp[2];
 				} else if (cmsg->cmsg_type == SO_RXQ_OVFL) {
 					memcpy(&obj->dropcnt, CMSG_DATA(cmsg), sizeof(__u32));
 				}
@@ -831,11 +857,9 @@ int main(int argc, char **argv)
 			/* build common log format output */
 			if ((log) || ((logfrmt) && (silent == SILENT_OFF))) {
 
-				alen = sprint_timestamp(afrbuf, logtimestamp,
-							  &tv, &last_tv);
+				alen = sprint_timestamp(afrbuf, logtimestamp, use_ns, &ts, &last_ts);
 
-				alen += sprintf(afrbuf + alen, "%*s ",
-						  max_devname_len, devname[idx]);
+				alen += sprintf(afrbuf + alen, "%*s ", max_devname_len, devname[idx]);
 
 				alen += snprintf_canframe(afrbuf + alen, sizeof(afrbuf) - alen, &cu, 0);
 			}
@@ -861,7 +885,7 @@ int main(int argc, char **argv)
 
 			/* print (colored) long CAN frame style to stdout */
 			alen = sprintf(afrbuf, " %s", (color > 2) ? col_on[idx % MAXCOL] : "");
-			alen += sprint_timestamp(afrbuf + alen, timestamp, &tv, &last_tv);
+			alen += sprint_timestamp(afrbuf + alen, timestamp, use_ns, &ts, &last_ts);
 			alen += sprintf(afrbuf + alen, " %s%*s",
 					  (color && (color < 3)) ? col_on[idx % MAXCOL] : "",
 					  max_devname_len, devname[idx]);

canplayer-bisect

@@ -0,0 +1,205 @@
+#!/bin/bash
+
+if [ -z "${CANPLAYER}" ]; then
+	CANPLAYER="canplayer"
+fi
+
+die() {
+	echo "$*" > /dev/stderr
+	exit 1
+}
+
+usage() {
+	echo "canplayer-bisect <start|stop|clean|good|yes|bad|no|again|where|undo> <logfile> <canplayer options>"
+}
+
+is_ready() {
+	if [ ! -d .canplayer-bisect ]; then
+		usage
+		exit 1
+	fi
+
+	return 0
+}
+
+setup() {
+	is_ready
+
+	LOGFILE=$(cat .canplayer-bisect/logfile |head -n 1)
+
+	SAVED_LEN="$(cat .canplayer-bisect/len|tail -n 1)"
+	LEN="$(wc -l ${LOGFILE} | awk '{ print $1 }')"
+
+	if [ "$LEN" != "$SAVED_LEN" ]; then
+		die "logfile has changed size. restart"
+	fi
+
+	CANPLAYER_ARGS=$(cat .canplayer-bisect/args |head -n 1)
+
+	HEAD="$(cat .canplayer-bisect/head |tail -n 1)"
+	TAIL="$(cat .canplayer-bisect/tail |tail -n 1)"
+}
+
+back() {
+	HEAD="$(cat .canplayer-bisect/head |tail -n 2 |head -n1)"
+	TAIL="$(cat .canplayer-bisect/tail |tail -n 2 |head -n1)"
+}
+
+do_undo() {
+	sed -i '$ d' .canplayer-bisect/head
+	sed -i '$ d' .canplayer-bisect/tail
+}
+
+teardown() {
+	mkdir -p .canplayer-bisect
+	echo $LEN > .canplayer-bisect/len
+	echo $LOGFILE > .canplayer-bisect/logfile
+	echo $CANPLAYER_ARGS > .canplayer-bisect/args
+
+	echo $HEAD >> .canplayer-bisect/head
+	echo $TAIL >> .canplayer-bisect/tail
+}
+
+show() {
+	cat $LOGFILE | sed -n ${HEAD},${TAIL}p
+}
+
+play() {
+	#we *could* pipe directly to canplayer, but then the user can't add -l i to CANPLAYER_ARGS to hunt for packets using looped playback
+	the_show="$(mktemp)"
+	trap "rm -rf \"${the_show}\"" EXIT
+
+	show > "${the_show}"
+	"${CANPLAYER}" ${CANPLAYER_ARGS} -I "${the_show}"
+}
+
+do_show() {
+	setup
+
+	show
+}
+
+check_heads_n_tails() {
+	if [ $HEAD -eq $TAIL ]; then
+		do_stop
+	fi
+}
+
+do_good() {
+	setup
+
+	check_heads_n_tails
+
+	if [ $(( $HEAD + 1 )) -eq $TAIL ]; then
+		TAIL=$HEAD
+	else
+		TAIL=$(( ( $TAIL - $HEAD ) / 2 + $HEAD - 1 ))
+	fi
+
+	teardown
+	play
+}
+
+do_bad() {
+	setup
+
+	check_heads_n_tails
+
+	back
+	if [ $(( $HEAD + 1 )) -eq $TAIL ]; then
+		HEAD=$TAIL
+	else
+		HEAD=$(( ( $TAIL - $HEAD ) / 2 + $HEAD ))
+	fi
+
+	teardown
+	play
+}
+
+do_again() {
+	setup
+	play
+}
+
+do_start() {
+	do_clean
+
+	LEN="$(wc -l ${LOGFILE} | awk '{ print $1 }')"
+
+	HEAD=1
+	TAIL=$LEN
+
+	echo "assuming logfile contains the packets you seek... bisecting to first half"
+
+	teardown
+	play
+}
+
+do_where() {
+	setup
+	echo "between $HEAD and $TAIL (+$(( $TAIL - $HEAD ))) of $LOGFILE"
+}
+
+do_stop() {
+	setup
+
+	if [ "$COMMAND" == "no" ]; then
+		echo "failed to find what you were looking for"
+		exit 1
+	else
+		echo "the packets you seek are:"
+		do_where
+		exit 0
+	fi
+}
+
+do_clean() {
+	rm -rf .canplayer-bisect
+}
+
+if [ -z "$1" ]; then
+	usage
+	exit 1
+fi
+COMMAND=$1
+
+if [ ! -d .canplayer-bisect ] && [ ! -z "$2" ] && [ ! -e "$2" ]; then
+	usage
+	exit 1
+fi
+LOGFILE="$2"
+
+shift
+shift
+CANPLAYER_ARGS="$*"
+
+case "$COMMAND" in
+	start)
+		do_start
+	;;
+	stop)
+		do_stop
+	;;
+	clean)
+		do_clean
+	;;
+	good|yes)
+		do_good
+	;;
+	bad|no)
+		do_bad
+	;;
+	again)
+		do_again
+	;;
+	where)
+		do_where
+	;;
+	undo)
+		do_undo
+	;;
+	show)
+		do_show
+	;;
+esac
+

canplayer.c

@@ -68,7 +68,7 @@
 #endif
 
 #define DEVSZ 22 /* IFNAMSZ + 6 */
-#define TIMESZ sizeof("(1345212884.318850)   ")
+#define TIMESZ sizeof("(1345212884.318850123)   ")
 #define BUFSZ (TIMESZ + DEVSZ + AFRSZ)
 
 /* adapt sscanf() functions below on error */
@@ -452,14 +452,20 @@ int main(int argc, char **argv)
 			return 1;
 		}
 		log_tv.tv_sec = sec;
-		log_tv.tv_usec = usec;
 
 		/*
-		 * ensure the fractions of seconds are 6 decimal places long to catch
+		 * ensure the fractions of seconds are 6 or 9 decimal places long to catch
 		 * 3rd party or handcrafted logfiles that treat the timestamp as float
 		 */
-		if (strchr(buf, ')') - strchr(buf, '.') != 7) {
-			fprintf(stderr, "timestamp format in logfile requires 6 decimal places\n");
+		switch (strchr(buf, ')') - strchr(buf, '.')) {
+		case 7: //6
+			log_tv.tv_usec = usec;
+			break;
+		case 10: //9
+			log_tv.tv_usec = usec / 1000;
+			break;
+		default:
+			fprintf(stderr, "timestamp format in logfile requires 6 or 9 decimal places\n");
 			return 1;
 		}
 
@@ -541,19 +547,25 @@ int main(int argc, char **argv)
 					break;
 				}
 
-				if (sscanf(buf, "(%llu.%llu) %s %s", &sec, &usec, device, afrbuf) != 4) {
+				if (sscanf(buf, "(%llu.%llu) %21s %6299s", &sec, &usec, device, afrbuf) != 4) {
 					fprintf(stderr, "incorrect line format in logfile\n");
 					return 1;
 				}
 				log_tv.tv_sec = sec;
-				log_tv.tv_usec = usec;
 
 				/*
-				 * ensure the fractions of seconds are 6 decimal places long to catch
+				 * ensure the fractions of seconds are 6 or 9 decimal places long to catch
 				 * 3rd party or handcrafted logfiles that treat the timestamp as float
 				 */
-				if (strchr(buf, ')') - strchr(buf, '.') != 7) {
-					fprintf(stderr, "timestamp format in logfile requires 6 decimal places\n");
+				switch (strchr(buf, ')') - strchr(buf, '.')) {
+				case 7: //6
+					log_tv.tv_usec = usec;
+					break;
+				case 10: //9
+					log_tv.tv_usec = usec / 1000;
+					break;
+				default:
+					fprintf(stderr, "timestamp format in logfile requires 6 or 9 decimal places\n");
 					return 1;
 				}
 

log2asc.c

@@ -296,7 +296,7 @@ static void canxl_asc(cu_t *cu, int devno, int mtu,
 
 #define DEVSZ 22
 #define EXTRASZ 20
-#define TIMESZ sizeof("(1345212884.318850)   ")
+#define TIMESZ sizeof("(1345212884.318850123)   ")
 #define BUFSZ (DEVSZ + AFRSZ + EXTRASZ + TIMESZ)
 
 /* adapt sscanf() functions below on error */
@@ -407,7 +407,22 @@ int main(int argc, char **argv)
 			}
 		}
 		tv.tv_sec = sec;
-		tv.tv_usec = usec;
+
+		/*
+		 * ensure the fractions of seconds are 6 or 9 decimal places long to catch
+		 * 3rd party or handcrafted logfiles that treat the timestamp as float
+		 */
+		switch (strchr(buf, ')') - strchr(buf, '.')) {
+		case 7: //6
+			tv.tv_usec = usec;
+			break;
+		case 10: //9
+			tv.tv_usec = usec / 1000;
+			break;
+		default:
+			fprintf(stderr, "timestamp format in logfile requires 6 or 9 decimal places\n");
+			return 1;
+		}
 
 		if (print_banner) { /* print banner */
 			print_banner = 0;

log2long.c

@@ -51,7 +51,7 @@
 #include "lib.h"
 
 #define DEVSZ 22
-#define TIMESZ 22 /* sizeof("(1345212884.318850)   ") */
+#define TIMESZ 25 /* sizeof("(1345212884.318850123)   ") */
 #define BUFSZ (DEVSZ + AFRSZ + TIMESZ)
 
 /* adapt sscanf() functions below on error */
@@ -61,7 +61,7 @@
 #if (DEVSZ != 22)
 #error "DEVSZ value does not fit sscanf restrictions!"
 #endif
-#if (TIMESZ != 22)
+#if (TIMESZ != 25)
 #error "TIMESZ value does not fit sscanf restrictions!"
 #endif
 
@@ -78,7 +78,7 @@ int main(void)
 			return 1;
 		}
 
-		if (sscanf(buf, "%21s %21s %6299s", timestamp, device, afrbuf) != 3)
+		if (sscanf(buf, "%24s %21s %6299s", timestamp, device, afrbuf) != 3)
 			return 1;
 
 		mtu = parse_canframe(afrbuf, &cu);