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--