Subject: Re: kern/22551: panic: kernel diagnostic assertion to_ticks>=0 failed: kern_timeout.c line 295
To: None <gnats-bugs@netbsd.org>
From: Andreas Wrede <andreas@planix.com>
List: netbsd-bugs
Date: 01/26/2005 15:47:24
--Apple-Mail-9--383774530
Content-Transfer-Encoding: 7bit
Content-Type: text/plain; charset=US-ASCII; format=flowed

After two more panics "caused" by outgoing email messages, I installed 
the following work-around:

RCS file: /cvsroot/src/sys/kern/kern_timeout.c,v
retrieving revision 1.13
diff -u -r1.13 kern_timeout.c
--- sys/kern/kern_timeout.c     30 Oct 2003 04:32:56 -0000      1.13
+++ sys/kern/kern_timeout.c     26 Jan 2005 20:21:53 -0000
@@ -278,7 +278,9 @@
  {
         int s, old_time;

-       KASSERT(to_ticks >= 0);
+/*     KASSERT(to_ticks >= 0); */
+       if (to_ticks < 0)
+               printf("BANG! to_ticks negative: %d\n", to_ticks);

         CALLOUT_LOCK(s);

With the patch in place, I see to_tick values like -250, -200 and -100.

The question is, what effect does a negative value of to_ticks have on 
the scheduling (and later executing) of the callout?  I suspect all is 
well, as otherwise non-DIAGNOSTIC kernels would experience frequent 
problems.

I am still not sure of what triggers the problem.  The only unusual 
thing I see in the TCP packets are two consecutive packets received 
with identical timestamps.


On 24-Jan-05, at 2:43 PM, Andreas Wrede wrote:

> The following reply was made to PR kern/22551; it has been noted by 
> GNATS.
>
> From: Andreas Wrede <andreas@planix.com>
> To: gnats-bugs@netbsd.org
> Cc:
> Subject: Re: kern/22551: panic: kernel diagnostic assertion 
> to_ticks>=0 failed: kern_timeout.c line 295
> Date: Mon, 24 Jan 2005 14:41:00 -0500
>
>  --Apple-Mail-18--560558732
>  Content-Transfer-Encoding: 7bit
>  Content-Type: text/plain; charset=US-ASCII; format=flowed
>
>  This morning I got, in rapid succession, five of the above panics on a
>  NetBSD 2.0_STABLE server. After comparing packet traces from and to 
> the
>  affected machine at the time of the various crashes, I found that
>  attempts by the SMTP server to deliver a message to  64.202.166.12 
> will
>  trigger the assert.  I manually confirmed this on a -current system
>  (2.99.13 as of Jan 13), about one in three connections resulted in a
>  panic (64.202.166.12 is probably some form of load balancer, as
>  different 220 messages are received on successive connects):
>
>  $ telnet  64.202.166.12 smtp
>  Connected to smtp.secureserver.net.
>  Escape character is '^]'.
>  220 pre-smtp01-02.prod.mesa1.secureserver.net ESMTP
>  EHLO whome.planix.com
>  250-pre-smtp01-02.prod.mesa1.secureserver.net
>  250-PIPELINING
>  250-SIZE 31457280
>  250 8BITMIME
>  quit
>
>  panic: kernel diagnostic assertion "to_ticks >= 0" failed: file
>  "/m5/netbsd-2.0/src/sys/kern/kern_timeout.c", line 281
>  Begin traceback...
>  __main(c064df68,c06ad200,119,c065e3d8,719da9e0) at netbsd:__main
>  callout_schedule(c1b77b44,fffffed4,28,28,41f5133c) at
>  netbsd:callout_schedule+0xc5
>  tcp_output(c1b77b38,c12d0b00,0,0,cc4b2b2c) at netbsd:tcp_output+0x721
>  tcp_usrreq(c1b7fa4c,9,c12d0b00,0,0) at netbsd:tcp_usrreq+0x3c3
>  sosend(c1b7fa4c,0,cc436ec4,c12d0b00,0) at netbsd:sosend+0x347
>  soo_write(cb7f3d00,cb7f3d28,cc436ec4,c1abae80,1) at
>  netbsd:soo_write+0x1e
>  dofilewrite(cc4b2b2c,9,cb7f3d00,8223400,61) at netbsd:dofilewrite+0x81
>  sys_write(cc1d7c64,cc436f64,cc436f5c,0,cc436fa4) at
>  netbsd:sys_write+0x59
>  syscall_plain() at netbsd:syscall_plain+0x7e
>  --- syscall (number 4) ---
>  0x8097c57:
>  End traceback...
>  syncing disks... panic: kernel diagnostic assertion "to_ticks >= 0"
>  failed: file "/m5/netbsd-2.0/src/sys/kern/kern_timeout.c", line 281
>  Begin traceback...
>  __main(c064df68,c06ad200,119,c065e3d8,719daa41) at netbsd:__main
>  callout_schedule(c1b77b44,fffffed4,28,28,c03803f1) at
>  netbsd:callout_schedule+0xc5
>  tcp_output(c1b77b38,c159ba64,100,40,8) at netbsd:tcp_output+0x721
>  tcp_delack(c1b77b38,cc4368e4,1,cc4b2b2c,cc436910) at
>  netbsd:tcp_delack+0x7c
>  softclock(0,cc436904,c04b43fd,cc436910,3) at netbsd:softclock+0x259
>  softintr_dispatch(0,10,30,cc4b0010,c09d0010) at
>  netbsd:softintr_dispatch+0x73
>  Xsoftclock() at netbsd:Xsoftclock+0x25
>  --- interrupt ---
>  genfs_putpages(cc436aa4,0,cc436adc,c037b2ec,c056ee00) at
>  netbsd:genfs_putpages+0x5dc
>  VOP_PUTPAGES(cc4b60c8,0,0,0,0) at netbsd:VOP_PUTPAGES+0x40
>  ffs_full_fsync(cc436bc4,0,cc1d7c64,cc436b6c,10) at
>  netbsd:ffs_full_fsync+0x288
>  ffs_fsync(cc436bc4,cc4b60c8,10012,c037afb0,c056e640) at
>  netbsd:ffs_fsync+0x4c
>  VOP_FSYNC(cc4b60c8,c1abae80,0,0,0) at netbsd:VOP_FSYNC+0x4c
>  ffs_sync(c12e2200,2,c1abae80,cc4b2b2c,cc436c6c) at 
> netbsd:ffs_sync+0x1ea
>  sys_sync(cc1d7c64,0,0,0,100) at netbsd:sys_sync+0xba
>  vfs_shutdown(c06dff60,0,cc436ccc,c034fb28,100) at
>  netbsd:vfs_shutdown+0x5f
>  cpu_reboot(100,0,c12d0b00,c03620e9,c12c6a6c) at 
> netbsd:cpu_reboot+0x15f
>  panic(c06dff60,c064df68,c065e3d8,c06ad200,119) at netbsd:panic+0x108
>  __main(c064df68,c06ad200,119,c065e3d8,719da9e0) at netbsd:__main
>  callout_schedule(c1b77b44,fffffed4,28,28,41f5133c) at
>  netbsd:callout_schedule+0xc5
>  tcp_output(c1b77b38,c12d0b00,0,0,cc4b2b2c) at netbsd:tcp_output+0x721
>  tcp_usrreq(c1b7fa4c,9,c12d0b00,0,0) at netbsd:tcp_usrreq+0x3c3
>  sosend(c1b7fa4c,0,cc436ec4,c12d0b00,0) at netbsd:sosend+0x347
>  soo_write(cb7f3d00,cb7f3d28,cc436ec4,c1abae80,1) at
>  netbsd:soo_write+0x1e
>  dofilewrite(cc4b2b2c,9,cb7f3d00,8223400,61) at netbsd:dofilewrite+0x81
>  sys_write(cc1d7c64,cc436f64,cc436f5c,0,cc436fa4) at
>  netbsd:sys_write+0x59
>  syscall_plain() at netbsd:syscall_plain+0x7e
>  --- syscall (number 4) ---
>  0x8097c57:
>  End traceback...
>
>  dumping to dev 4,65 offset 757672
>
>  A kernel core dump is available.
>
>  Below is the detailed ethereal analysis of the TCP session involved:
>
>  No.     Time            Source                Destination
>  Protocol Info
>     16776 10:24:43.876414 204.29.161.33         64.202.166.12         
> TCP
>        65481 > smtp [SYN] Seq=0 Ack=0 Win=65535 Len=0 MSS=1460 WS=1 
> TSV=0
>  TSER=0
>
>  Frame 16776 (74 bytes on wire, 74 bytes captured)
>  Ethernet II, Src: 00:0e:0c:65:e3:a1, Dst: 00:d0:b7:7f:d3:65
>  Internet Protocol, Src Addr: 204.29.161.33 (204.29.161.33), Dst Addr:
>  64.202.166.12 (64.202.166.12)
>  Transmission Control Protocol, Src Port: 65481 (65481), Dst Port: smtp
>  (25), Seq: 0, Ack: 0, Len: 0
>
>  No.     Time            Source                Destination
>  Protocol Info
>     16792 10:24:43.967654 64.202.166.12         204.29.161.33         
> TCP
>        [TCP ZeroWindow] smtp > 65481 [SYN, ACK] Seq=0 Ack=1 Win=0 Len=0
>
>  Frame 16792 (54 bytes on wire, 54 bytes captured)
>  Ethernet II, Src: 00:d0:b7:7f:d3:65, Dst: 00:0e:0c:65:e3:a1
>  Internet Protocol, Src Addr: 64.202.166.12 (64.202.166.12), Dst Addr:
>  204.29.161.33 (204.29.161.33)
>  Transmission Control Protocol, Src Port: smtp (25), Dst Port: 65481
>  (65481), Seq: 0, Ack: 1, Len: 0
>
>  No.     Time            Source                Destination
>  Protocol Info
>     16793 10:24:43.967853 204.29.161.33         64.202.166.12         
> TCP
>        [TCP Window Full] 65481 > smtp [ACK] Seq=1 Ack=1 Win=65535 Len=0
>
>  Frame 16793 (64 bytes on wire, 64 bytes captured)
>  Ethernet II, Src: 00:0e:0c:65:e3:a1, Dst: 00:d0:b7:7f:d3:65
>  Internet Protocol, Src Addr: 204.29.161.33 (204.29.161.33), Dst Addr:
>  64.202.166.12 (64.202.166.12)
>  Transmission Control Protocol, Src Port: 65481 (65481), Dst Port: smtp
>  (25), Seq: 1, Ack: 1, Len: 0
>
>  No.     Time            Source                Destination
>  Protocol Info
>     16807 10:24:44.231541 64.202.166.12         204.29.161.33         
> TCP
>        [TCP Window Update] smtp > 65481 [ACK] Seq=1 Ack=1 Win=5792 
> Len=0
>
>  Frame 16807 (54 bytes on wire, 54 bytes captured)
>  Ethernet II, Src: 00:d0:b7:7f:d3:65, Dst: 00:0e:0c:65:e3:a1
>  Internet Protocol, Src Addr: 64.202.166.12 (64.202.166.12), Dst Addr:
>  204.29.161.33 (204.29.161.33)
>  Transmission Control Protocol, Src Port: smtp (25), Dst Port: 65481
>  (65481), Seq: 1, Ack: 1, Len: 0
>
>  No.     Time            Source                Destination
>  Protocol Info
>     16821 10:24:44.474880 64.202.166.12         204.29.161.33
>  SMTP     Response: 220 pre-smtp01-02.prod.mesa1.secureserver.net ESMTP
>
>  Frame 16821 (120 bytes on wire, 120 bytes captured)
>  Ethernet II, Src: 00:d0:b7:7f:d3:65, Dst: 00:0e:0c:65:e3:a1
>  Internet Protocol, Src Addr: 64.202.166.12 (64.202.166.12), Dst Addr:
>  204.29.161.33 (204.29.161.33)
>  Transmission Control Protocol, Src Port: smtp (25), Dst Port: 65481
>  (65481), Seq: 1, Ack: 1, Len: 54
>  Simple Mail Transfer Protocol
>
>  No.     Time            Source                Destination
>  Protocol Info
>     16822 10:24:44.475151 204.29.161.33         64.202.166.12
>  SMTP     Command: EHLO whome.planix.com
>
>  Frame 16822 (77 bytes on wire, 77 bytes captured)
>  Ethernet II, Src: 00:0e:0c:65:e3:a1, Dst: 00:d0:b7:7f:d3:65
>  Internet Protocol, Src Addr: 204.29.161.33 (204.29.161.33), Dst Addr:
>  64.202.166.12 (64.202.166.12)
>  Transmission Control Protocol, Src Port: 65481 (65481), Dst Port: smtp
>  (25), Seq: 1, Ack: 55, Len: 23
>  Simple Mail Transfer Protocol
>
>  No.     Time            Source                Destination
>  Protocol Info
>     16823 10:24:44.562170 64.202.166.12         204.29.161.33         
> TCP
>        smtp > 65481 [ACK] Seq=55 Ack=24 Win=5792 Len=0 TSV=226969747
>  TSER=10
>
>  Frame 16823 (66 bytes on wire, 66 bytes captured)
>  Ethernet II, Src: 00:d0:b7:7f:d3:65, Dst: 00:0e:0c:65:e3:a1
>  Internet Protocol, Src Addr: 64.202.166.12 (64.202.166.12), Dst Addr:
>  204.29.161.33 (204.29.161.33)
>  Transmission Control Protocol, Src Port: smtp (25), Dst Port: 65481
>  (65481), Seq: 55, Ack: 24, Len: 0
>
>  No.     Time            Source                Destination
>  Protocol Info
>     16824 10:24:44.563529 64.202.166.12         204.29.161.33
>  SMTP     Response: 250-pre-smtp01-02.prod.mesa1.secureserver.net
>
>
>  - The panic occurs here -
>
>  Frame 16824 (163 bytes on wire, 163 bytes captured)
>  Ethernet II, Src: 00:d0:b7:7f:d3:65, Dst: 00:0e:0c:65:e3:a1
>  Internet Protocol, Src Addr: 64.202.166.12 (64.202.166.12), Dst Addr:
>  204.29.161.33 (204.29.161.33)
>  Transmission Control Protocol, Src Port: smtp (25), Dst Port: 65481
>  (65481), Seq: 55, Ack: 24, Len: 97
>  Simple Mail Transfer Protocol
>
>  No.     Time            Source                Destination
>  Protocol Info
>     16827 10:24:44.844867 64.202.166.12         204.29.161.33
>  SMTP     [TCP Retransmission] Response:
>  250-pre-smtp01-02.prod.mesa1.secureserver.net
>
>  Frame 16827 (163 bytes on wire, 163 bytes captured)
>  Ethernet II, Src: 00:d0:b7:7f:d3:65, Dst: 00:0e:0c:65:e3:a1
>  Internet Protocol, Src Addr: 64.202.166.12 (64.202.166.12), Dst Addr:
>  204.29.161.33 (204.29.161.33)
>  Transmission Control Protocol, Src Port: smtp (25), Dst Port: 65481
>  (65481), Seq: 55, Ack: 24, Len: 97
>  Simple Mail Transfer Protocol
>
>  No.     Time            Source                Destination
>  Protocol Info
>     16832 10:24:45.424646 64.202.166.12         204.29.161.33
>  SMTP     [TCP Retransmission] Response:
>  250-pre-smtp01-02.prod.mesa1.secureserver.net
>
>  Frame 16832 (163 bytes on wire, 163 bytes captured)
>  Ethernet II, Src: 00:d0:b7:7f:d3:65, Dst: 00:0e:0c:65:e3:a1
>  Internet Protocol, Src Addr: 64.202.166.12 (64.202.166.12), Dst Addr:
>  204.29.161.33 (204.29.161.33)
>  Transmission Control Protocol, Src Port: smtp (25), Dst Port: 65481
>  (65481), Seq: 55, Ack: 24, Len: 97
>  Simple Mail Transfer Protocol
>
>  No.     Time            Source                Destination
>  Protocol Info
>     16836 10:24:46.584842 64.202.166.12         204.29.161.33
>  SMTP     [TCP Retransmission] Response:
>  250-pre-smtp01-02.prod.mesa1.secureserver.net
>
>  Frame 16836 (163 bytes on wire, 163 bytes captured)
>  Ethernet II, Src: 00:d0:b7:7f:d3:65, Dst: 00:0e:0c:65:e3:a1
>  Internet Protocol, Src Addr: 64.202.166.12 (64.202.166.12), Dst Addr:
>  204.29.161.33 (204.29.161.33)
>  Transmission Control Protocol, Src Port: smtp (25), Dst Port: 65481
>  (65481), Seq: 55, Ack: 24, Len: 97
>  Simple Mail Transfer Protocol
>
>  No.     Time            Source                Destination
>  Protocol Info
>     16847 10:24:48.904258 64.202.166.12         204.29.161.33
>  SMTP     [TCP Retransmission] Response:
>  250-pre-smtp01-02.prod.mesa1.secureserver.net
>
>  Frame 16847 (163 bytes on wire, 163 bytes captured)
>  Ethernet II, Src: 00:d0:b7:7f:d3:65, Dst: 00:0e:0c:65:e3:a1
>  Internet Protocol, Src Addr: 64.202.166.12 (64.202.166.12), Dst Addr:
>  204.29.161.33 (204.29.161.33)
>  Transmission Control Protocol, Src Port: smtp (25), Dst Port: 65481
>  (65481), Seq: 55, Ack: 24, Len: 97
>  Simple Mail Transfer Protocol
>
>  No.     Time            Source                Destination
>  Protocol Info
>     16870 10:24:53.544455 64.202.166.12         204.29.161.33
>  SMTP     [TCP Retransmission] Response:
>  250-pre-smtp01-02.prod.mesa1.secureserver.net
>
>  Frame 16870 (163 bytes on wire, 163 bytes captured)
>  Ethernet II, Src: 00:d0:b7:7f:d3:65, Dst: 00:0e:0c:65:e3:a1
>  Internet Protocol, Src Addr: 64.202.166.12 (64.202.166.12), Dst Addr:
>  204.29.161.33 (204.29.161.33)
>  Transmission Control Protocol, Src Port: smtp (25), Dst Port: 65481
>  (65481), Seq: 55, Ack: 24, Len: 97
>  Simple Mail Transfer Protocol
>
>  No.     Time            Source                Destination
>  Protocol Info
>     16937 10:25:02.823802 64.202.166.12         204.29.161.33
>  SMTP     [TCP Retransmission] Response:
>  250-pre-smtp01-02.prod.mesa1.secureserver.net
>
>  Frame 16937 (163 bytes on wire, 163 bytes captured)
>  Ethernet II, Src: 00:d0:b7:7f:d3:65, Dst: 00:0e:0c:65:e3:a1
>  Internet Protocol, Src Addr: 64.202.166.12 (64.202.166.12), Dst Addr:
>  204.29.161.33 (204.29.161.33)
>  Transmission Control Protocol, Src Port: smtp (25), Dst Port: 65481
>  (65481), Seq: 55, Ack: 24, Len: 97
>  Simple Mail Transfer Protocol

-- 
	aew

--Apple-Mail-9--383774530
content-type: application/pgp-signature; x-mac-type=70674453;
	name=PGP.sig
content-description: This is a digitally signed message part
content-disposition: inline; filename=PGP.sig
content-transfer-encoding: 7bit

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.2.4 (Darwin)

iD8DBQFB+AHeEh/h9J/TQyERAj8zAKDoPbIBywYxsVUe8fPqQN7Ns4PEiQCeIx4R
dB8mRQcpQ8ktqSy15xjK/f8=
=xOID
-----END PGP SIGNATURE-----

--Apple-Mail-9--383774530--