[gnutls-devel] FTBFS[kfreebsd]: tests/mini-loss-time race

[Andreas Metzler]

Hello,

this is http://bugs.debian.org/813598 reported by Steven Chamberlain:

Package: gnutls28
Version: 3.4.8-3
Severity: important

Hi,

gnutls28 tests/mini-loss-time fails about 20% of the time when I try it
on kfreebsd-amd64.  I think probably introduced by this commit:
https://gitlab.com/gnutls/gnutls/commit/e2a3ad31c487cbce997a08dddc55db639b60c024

The failure happens at ~60 seconds elapsed, when some (expected) timeout
is reached.  The child always exits first, and closes fds:

(49946 101730 = child)
49946 101730 mini-loss-time 60.187211 CALL  close(0x4)                      
49946 101730 mini-loss-time 60.187244 RET   close 0                         
49946 101730 mini-loss-time 60.187346 CALL  close(0x3)                      
49946 101730 mini-loss-time 60.187363 RET   close 0                         
49946 101730 mini-loss-time 60.187830 CALL  exit(0)                         

The parent receives SIGCHLD, and some wait() call on the child pid
returns:

(49871 102302 = parent)
49871 102302 mini-loss-time 60.188448 RET   select -1 errno 4 Interrupted system call
49871 102302 mini-loss-time 60.188572 PSIG  SIGCHLD caught handler=0x401570 mask=0x0 code=CLD_EXITED
49871 102302 mini-loss-time 60.188594 CALL  wait4(0xffffffff,0x7fffffffdd44,0,0)
49871 102302 mini-loss-time 60.188657 RET   wait4 49946/0xc31a              
49871 102302 mini-loss-time 60.188673 CALL  sigreturn(0x7fffffffdd70)       
49871 102302 mini-loss-time 60.188689 RET   sigreturn JUSTRETURN            
49871 102302 mini-loss-time 60.188713 CALL  clock_gettime(0,0x7fffffffe320) 
49871 102302 mini-loss-time 60.188808 RET   clock_gettime 0                 
49871 102302 mini-loss-time 60.188831 CALL  clock_gettime(0,0x7fffffffe320) 
49871 102302 mini-loss-time 60.188847 RET   clock_gettime 0                 

In the successful case, the parent exits now.

In the failure case, the parent tries to read something from an fd
first, I guess a pipe that was just closed at the other end
(maybe the server didn't time out quite yet?) :

(50000 101614 = parent)
50000 101614 mini-loss-time 59.273668 CALL  recvfrom(0x5,0x624833,0x415c,0,0,0)
50000 101614 mini-loss-time 59.273686 RET   recvfrom -1 errno 54 Connection reset by peer

leading to GNUTLS_E_PUSH_ERROR rather than expected GNUTLS_E_TIMEDOUT.

The attached ktrace dumps can be compared using vimdiff to help
study this.  I haven't tested on GNU/Linux.

If I lower the server timeout to 29 seconds, I haven't seen this failure
any more.

--- tests/mini-loss-time.c.orig
+++ tests/mini-loss-time.c
@@ -196,7 +196,7 @@
 
        gnutls_init(&session, GNUTLS_SERVER | GNUTLS_DATAGRAM);
        gnutls_dtls_set_mtu(session, 1500);
-       gnutls_dtls_set_timeouts(session, 1 * 1000, 30 * 1000);
+       gnutls_dtls_set_timeouts(session, 1 * 1000, 29 * 1000);
 
        /* avoid calling all the priority functions, since the defaults
         * are adequate.

Thanks!

-- System Information:
Debian Release: stretch/sid
  APT prefers unstable
  APT policy: (500, 'unstable'), (1, 'experimental')
Architecture: kfreebsd-amd64 (x86_64)

Kernel: kFreeBSD 10.1-0-amd64
Locale: LANG=en_GB.UTF-8, LC_CTYPE=en_GB.UTF-8 (charmap=UTF-8)
Shell: /bin/sh linked to /bin/dash
-------------- next part --------------
A non-text attachment was scrubbed...
Name: kdump.fail.gz
Type: application/gzip
Size: 16737 bytes
Desc: not available
URL: </pipermail/attachments/20160214/028feb85/attachment-0002.bin>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: kdump.ok.gz
Type: application/gzip
Size: 16615 bytes
Desc: not available
URL: </pipermail/attachments/20160214/028feb85/attachment-0003.bin>