A potential data race in axel.c and text.c

[wcventure]

Dear axel developers:

I found that there may exist a potential data race in the latest axel. And I have confirmed it with Google ThreadSanitizer, too. I wish you can help me check whether it is a real race, thanks! The following is the race report.

The sub-thread will call the setup_thread function to set up a connection. The function would write conn->last_transfer, and the access is protected by a lock pthread_mutex_lock(&conn->lock);. However, the main thread would read the value in the print_alternate_output_progress function without protected by a lock, leading to a potential data race.

/* Thread used to set up a connection */
static void * setup_thread(void *c)
{
	conn_t *conn = c;
	int oldstate;

	/* Allow this thread to be killed at any time. */
	pthread_setcancelstate(PTHREAD_CANCEL_ENABLE, &oldstate);
	pthread_setcanceltype(PTHREAD_CANCEL_ASYNCHRONOUS, &oldstate);

	pthread_mutex_lock(&conn->lock);
	if (conn_setup(conn)) {
		conn->last_transfer = axel_gettime();
		if (conn_exec(conn)) {
			conn->last_transfer = axel_gettime();
			conn->enabled = true;
			goto out;
		}
	}
    // ...
}

Also, see

axel/src/axel.c

Lines 827 to 832 in 9cedf8b

	pthread_mutex_lock(&conn->lock);
	if (conn_setup(conn)) {
	conn->last_transfer = axel_gettime();
	if (conn_exec(conn)) {
	conn->last_transfer = axel_gettime();
	conn->enabled = true;

.

The following is the function call by main thread. It read the value from conn->last_transfer without protected by a lock. The value of conn->last_transfer could be writed concurrently by sub-thread in setup_thread function, leading to a potential data race.

static void print_alternate_output_progress(axel_t *axel, char *progress, int width, off_t done, off_t total, double now)
{
	//...
	for (int i = 0; i < axel->conf->num_connections; i++) {
		int offset = axel->conn[i].currentbyte * width / total;

		if (axel->conn[i].currentbyte < axel->conn[i].lastbyte) {
			if (now <= axel->conn[i].last_transfer + axel->conf->connection_timeout / 2) {
				progress[offset] = alt_id(i);
			} else
				progress[offset] = '#';
		}
		memset(progress + offset + 1, ' ',
		       max(0, axel->conn[i].lastbyte * width / total - offset - 1));
	}
}

Also, see

axel/src/text.c

Lines 576 to 577 in 9cedf8b

	if (now <= axel->conn[i].last_transfer
	+ axel->conf->connection_timeout / 2) {

.

I have confirmed this data race with Google ThreadSanitizer, too. The following is the report from thread Sanitizer:

==================
WARNING: ThreadSanitizer: data race (pid=8947)
  Write of size 4 at 0x7bb000005204 by thread T2 (mutexes: write M2):
    #0 setup_thread /workdir/axel-2.17.10/axel-2.17.10/src/axel.c:835:24 (axel+0x4b6989)

  Previous read of size 4 at 0x7bb000005204 by main thread:
    #0 print_alternate_output_progress /workdir/axel-2.17.10/axel-2.17.10/src/text.c:576:29 (axel+0x4c9108)
    #1 print_alternate_output /workdir/axel-2.17.10/axel-2.17.10/src/text.c:616:3 (axel+0x4c85da)
    #2 main /workdir/axel-2.17.10/axel-2.17.10/src/text.c:406:5 (axel+0x4c7be1)

  Location is heap block of size 31608 at 0x7bb000000000 allocated by main thread:
    #0 calloc /home/brian/src/final/llvm-project/compiler-rt/lib/tsan/rtl/tsan_interceptors_posix.cpp:668:5 (axel+0x4237d0)
    #1 axel_new /workdir/axel-2.17.10/axel-2.17.10/src/axel.c:137:15 (axel+0x4b22f5)
    #2 main /workdir/axel-2.17.10/axel-2.17.10/src/text.c:312:10 (axel+0x4c71fb)

  Mutex M2 (0x7bb000005228) created at:
    #0 pthread_mutex_init /home/brian/src/final/llvm-project/compiler-rt/lib/tsan/rtl/tsan_interceptors_posix.cpp:1220:3 (axel+0x42639d)
    #1 axel_new /workdir/axel-2.17.10/axel-2.17.10/src/axel.c:142:3 (axel+0x4b242f)
    #2 main /workdir/axel-2.17.10/axel-2.17.10/src/text.c:312:10 (axel+0x4c71fb)

  Thread T2 (tid=8950, running) created by main thread at:
    #0 pthread_create /home/brian/src/final/llvm-project/compiler-rt/lib/tsan/rtl/tsan_interceptors_posix.cpp:962:3 (axel+0x424e1b)
    #1 axel_start /workdir/axel-2.17.10/axel-2.17.10/src/axel.c:472:8 (axel+0x4b6291)
    #2 main /workdir/axel-2.17.10/axel-2.17.10/src/text.c:380:2 (axel+0x4c7895)

SUMMARY: ThreadSanitizer: data race /workdir/axel-2.17.10/axel-2.17.10/src/axel.c:835:24 in setup_thread
==================
==================
WARNING: ThreadSanitizer: data race (pid=8947)
  Write of size 4 at 0x7bb000007b2c by thread T3 (mutexes: write M3):
    #0 setup_thread /workdir/axel-2.17.10/axel-2.17.10/src/axel.c:835:24 (axel+0x4b6989)

  Previous read of size 4 at 0x7bb000007b2c by main thread:
    #0 print_alternate_output_progress /workdir/axel-2.17.10/axel-2.17.10/src/text.c:576:29 (axel+0x4c9108)
    #1 print_alternate_output /workdir/axel-2.17.10/axel-2.17.10/src/text.c:616:3 (axel+0x4c85da)
    #2 main /workdir/axel-2.17.10/axel-2.17.10/src/text.c:406:5 (axel+0x4c7be1)

  Location is heap block of size 31608 at 0x7bb000000000 allocated by main thread:
    #0 calloc /home/brian/src/final/llvm-project/compiler-rt/lib/tsan/rtl/tsan_interceptors_posix.cpp:668:5 (axel+0x4237d0)
    #1 axel_new /workdir/axel-2.17.10/axel-2.17.10/src/axel.c:137:15 (axel+0x4b22f5)
    #2 main /workdir/axel-2.17.10/axel-2.17.10/src/text.c:312:10 (axel+0x4c71fb)

  Mutex M3 (0x7bb000007b50) created at:
    #0 pthread_mutex_init /home/brian/src/final/llvm-project/compiler-rt/lib/tsan/rtl/tsan_interceptors_posix.cpp:1220:3 (axel+0x42639d)
    #1 axel_new /workdir/axel-2.17.10/axel-2.17.10/src/axel.c:142:3 (axel+0x4b242f)
    #2 main /workdir/axel-2.17.10/axel-2.17.10/src/text.c:312:10 (axel+0x4c71fb)

  Thread T3 (tid=8951, running) created by main thread at:
    #0 pthread_create /home/brian/src/final/llvm-project/compiler-rt/lib/tsan/rtl/tsan_interceptors_posix.cpp:962:3 (axel+0x424e1b)
    #1 axel_start /workdir/axel-2.17.10/axel-2.17.10/src/axel.c:472:8 (axel+0x4b6291)
    #2 main /workdir/axel-2.17.10/axel-2.17.10/src/text.c:380:2 (axel+0x4c7895)

SUMMARY: ThreadSanitizer: data race /workdir/axel-2.17.10/axel-2.17.10/src/axel.c:835:24 in setup_thread
==================

I am not sure whether this race could cause the real-time progress display to be inconsistent with the actual situation. I wish you can help me check whether it is a real race, thanks!

[ismaell]

In practice the value read is only wrong if the read isn't atomic in the architecture and it happens to read just when the update carries over to the next word. OTOH, that value is used only for reporting, so no harm can be done.

Patches are welcome as long as no extra locks are required, I would rather not add a lock for that.