[Home]

Summary:ASTERISK-02397: NOTICEs from sched.c
Reporter:Roy Sigurd Karlsbakk (rkarlsba)Labels:
Date Opened:2004-09-14 05:56:54Date Closed:2004-09-25 02:04:40
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Core/General
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:
Description:Starting from (around) CVS sept 12, I get these NOTICEs every few minutes:

Sep 14 12:42:42 NOTICE[1085819824]: sched.c:290 ast_sched_del: Attempted to delete non-existant schedule entry 0
Comments:By: Mark Spencer (markster) 2004-09-14 08:28:56

Can you tell what event it occurs near?  (e.g. SIP registration, receiving SIP registration, IAX registration, receiving IAX registration, etc)
By: Roy Sigurd Karlsbakk (rkarlsba) 2004-09-14 08:38:54

This:

sipgw1*CLI>

Sip read:
REGISTER sip:BRIIZ.NO SIP/2.0
Via: SIP/2.0/UDP 80.239.107.66:48186;rport;branch=z9hG4bK502777E95E104D909606489495692700
From: Atle Nygaard <sip:1000009@BRIIZ.NO:1025>;tag=734148128
To: Atle Nygaard <sip:1000009@BRIIZ.NO:1025>
Contact: "Atle Nygaard" <sip:1000009@80.239.107.66:48186>
Call-ID: 8E2D63AB0E714B5AA81AFAC17AB10400@BRIIZ.NO
CSeq: 28789 REGISTER
Expires: 60
Max-Forwards: 70
User-Agent: X-PRO release 1103g
Content-Length: 0


11 headers, 0 lines
Using latest request as basis request
Sending to 80.239.107.66 : 48186 (NAT)
Transmitting (NAT):
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 80.239.107.66:48186;branch=z9hG4bK502777E95E104D909606489495692700;received=80.239.107.66;rport=48186
From: Atle Nygaard <sip:1000009@BRIIZ.NO:1025>;tag=734148128
To: Atle Nygaard <sip:1000009@BRIIZ.NO:1025>;tag=as380a2814
Call-ID: 8E2D63AB0E714B5AA81AFAC17AB10400@BRIIZ.NO
CSeq: 28789 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER
Contact: <sip:1000009@213.160.242.5>
Content-Length: 0


to 80.239.107.66:48186
Transmitting (NAT):
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 80.239.107.66:48186;branch=z9hG4bK502777E95E104D909606489495692700;received=80.239.107.66;rport=48186
From: Atle Nygaard <sip:1000009@BRIIZ.NO:1025>;tag=734148128
To: Atle Nygaard <sip:1000009@BRIIZ.NO:1025>;tag=as380a2814
Call-ID: 8E2D63AB0E714B5AA81AFAC17AB10400@BRIIZ.NO
CSeq: 28789 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER
Contact: <sip:1000009@213.160.242.5>
WWW-Authenticate: Digest realm="asterisk", nonce="6ef6607b"
Content-Length: 0


to 80.239.107.66:48186
Scheduling destruction of call '8E2D63AB0E714B5AA81AFAC17AB10400@BRIIZ.NO' in 15000 ms
sipgw1*CLI>

Sip read:
REGISTER sip:BRIIZ.NO SIP/2.0
Via: SIP/2.0/UDP 80.239.107.66:48186;rport;branch=z9hG4bKC59D99274DBB470F9A64DCBD2E43965B
From: Atle Nygaard <sip:1000009@BRIIZ.NO:1025>;tag=734148128
To: Atle Nygaard <sip:1000009@BRIIZ.NO:1025>
Contact: "Atle Nygaard" <sip:1000009@80.239.107.66:48186>
Call-ID: 8E2D63AB0E714B5AA81AFAC17AB10400@BRIIZ.NO
CSeq: 28790 REGISTER
Expires: 60
Authorization: Digest username="1000009",realm="asterisk",nonce="6ef6607b",response="e6d2eb41d77bbde783ee9799a140aa67",uri="sip:BRIIZ.NO"
Max-Forwards: 70
User-Agent: X-PRO release 1103g
Content-Length: 0


12 headers, 0 lines
Using latest request as basis request
Sending to 80.239.107.66 : 48186 (NAT)
Transmitting (NAT):
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 80.239.107.66:48186;branch=z9hG4bKC59D99274DBB470F9A64DCBD2E43965B;received=80.239.107.66;rport=48186
From: Atle Nygaard <sip:1000009@BRIIZ.NO:1025>;tag=734148128
To: Atle Nygaard <sip:1000009@BRIIZ.NO:1025>;tag=as380a2814
Call-ID: 8E2D63AB0E714B5AA81AFAC17AB10400@BRIIZ.NO
CSeq: 28790 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER
Contact: <sip:1000009@213.160.242.5>
Content-Length: 0


to 80.239.107.66:48186
   -- Saved useragent "X-PRO release 1103g" for peer 1000009
Transmitting (NAT):
SIP/2.0 200 OK
Via: SIP/2.0/UDP 80.239.107.66:48186;branch=z9hG4bKC59D99274DBB470F9A64DCBD2E43965B;received=80.239.107.66;rport=48186
From: Atle Nygaard <sip:1000009@BRIIZ.NO:1025>;tag=734148128
To: Atle Nygaard <sip:1000009@BRIIZ.NO:1025>;tag=as380a2814
Call-ID: 8E2D63AB0E714B5AA81AFAC17AB10400@BRIIZ.NO
CSeq: 28790 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER
Expires: 60
Contact: <sip:1000009@80.239.107.66:48186>;expires=60
Date: Tue, 14 Sep 2004 13:37:25 GMT
Content-Length: 0


to 80.239.107.66:48186
Scheduling destruction of call '8E2D63AB0E714B5AA81AFAC17AB10400@BRIIZ.NO' in 15000 ms
Sep 14 15:37:25 NOTICE[1085819824]: chan_sip.c:7499 handle_request: Registration from 'sip:1000020@briiz.no' failed for '211.75.40.106'
By: Mark Spencer (markster) 2004-09-14 08:42:59

The NOTICE in your trace is not the NOTICE this bug report is about, the one in the trace is an invalid authentication from some other host.

Can you please supply a trace that includes the NOTICE about the schedule entry 0?  thanks!
By: Roy Sigurd Karlsbakk (rkarlsba) 2004-09-14 08:52:21

Sorry
Tired
Bah

See below for more, and hopefully better info

sipgw1*CLI> NEW LOG
No such command 'NEW' (type 'help' for help)
sipgw1*CLI>

Sip read:
REGISTER sip:213.160.242.5 SIP/2.0
Content-Length: 0
Contact: <sip:1000004@80.239.107.66:1025>
Call-ID: 306D7586-9F20-4819-8702-BA5CF77C8D67@192.168.1.100
Max-Forwards: 70
From: <sip:1000004@213.160.242.5:1025>;tag=77984926
CSeq: 432 REGISTER
To: <sip:1000004@213.160.242.5:1025>
Via: SIP/2.0/UDP 80.239.107.66:1025;branch=z9hG4bKc0a801660131c9b14146f70f0000068b0000050d


9 headers, 0 lines
Using latest request as basis request
Sending to 80.239.107.66 : 1025 (NAT)
Transmitting (NAT):
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 80.239.107.66:1025;branch=z9hG4bKc0a801660131c9b14146f70f0000068b0000050d;received=80.239.107.66;rport=5060
From: <sip:1000004@213.160.242.5:1025>;tag=77984926
To: <sip:1000004@213.160.242.5:1025>;tag=as131d60f7
Call-ID: 306D7586-9F20-4819-8702-BA5CF77C8D67@192.168.1.100
CSeq: 432 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER
Contact: <sip:1000004@213.160.242.5>
Content-Length: 0


to 80.239.107.66:5060
Transmitting (NAT):
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 80.239.107.66:1025;branch=z9hG4bKc0a801660131c9b14146f70f0000068b0000050d;received=80.239.107.66;rport=5060
From: <sip:1000004@213.160.242.5:1025>;tag=77984926
To: <sip:1000004@213.160.242.5:1025>;tag=as131d60f7
Call-ID: 306D7586-9F20-4819-8702-BA5CF77C8D67@192.168.1.100
CSeq: 432 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER
Contact: <sip:1000004@213.160.242.5>
WWW-Authenticate: Digest realm="asterisk", nonce="4de89180"
Content-Length: 0


to 80.239.107.66:5060
Scheduling destruction of call '306D7586-9F20-4819-8702-BA5CF77C8D67@192.168.1.100' in 15000 ms
sipgw1*CLI>

Sip read:
REGISTER sip:213.160.242.5 SIP/2.0
Content-Length: 0
Contact: <sip:1000004@80.239.107.66:1025>
Call-ID: 306D7586-9F20-4819-8702-BA5CF77C8D67@192.168.1.100
Max-Forwards: 70
From: <sip:1000004@213.160.242.5:1025>;tag=77984976
CSeq: 433 REGISTER
To: <sip:1000004@213.160.242.5:1025>
Via: SIP/2.0/UDP 80.239.107.66:1025;branch=z9hG4bKc0a801660131c9b14146f70f0000345c00000510
Authorization: Digest username="1000004",realm="asterisk",nonce="4de89180",uri="sip:213.160.242.5",response="40cf56b831ef25f5f9dfa0a655c93612"


10 headers, 0 lines
Using latest request as basis request
Sending to 80.239.107.66 : 1025 (NAT)
Transmitting (NAT):
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 80.239.107.66:1025;branch=z9hG4bKc0a801660131c9b14146f70f0000345c00000510;received=80.239.107.66;rport=5060
From: <sip:1000004@213.160.242.5:1025>;tag=77984976
To: <sip:1000004@213.160.242.5:1025>;tag=as4dd63bcf
Call-ID: 306D7586-9F20-4819-8702-BA5CF77C8D67@192.168.1.100
CSeq: 433 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER
Contact: <sip:1000004@213.160.242.5>
Content-Length: 0


to 80.239.107.66:5060
Transmitting (NAT):
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 80.239.107.66:1025;branch=z9hG4bKc0a801660131c9b14146f70f0000345c00000510;received=80.239.107.66;rport=5060
From: <sip:1000004@213.160.242.5:1025>;tag=77984976
To: <sip:1000004@213.160.242.5:1025>;tag=as4dd63bcf
Call-ID: 306D7586-9F20-4819-8702-BA5CF77C8D67@192.168.1.100
CSeq: 433 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER
Contact: <sip:1000004@213.160.242.5>
WWW-Authenticate: Digest realm="asterisk", nonce="00109c56"
Content-Length: 0


to 80.239.107.66:5060
Scheduling destruction of call '306D7586-9F20-4819-8702-BA5CF77C8D67@192.168.1.100' in 15000 ms
Destroying call '306D7586-9F20-4819-8702-BA5CF77C8D67@192.168.1.100'
Destroying call '306D7586-9F20-4819-8702-BA5CF77C8D67@192.168.1.100'
sipgw1*CLI>
sipgw1*CLI>

Sip read:
REGISTER sip:BRIIZ.NO SIP/2.0
Via: SIP/2.0/UDP 80.239.107.66:48186;rport;branch=z9hG4bK5590A407ADDE483F9C8E4F866DF0934A
From: Atle Nygaard <sip:1000009@BRIIZ.NO:1025>;tag=734148128
To: Atle Nygaard <sip:1000009@BRIIZ.NO:1025>
Contact: "Atle Nygaard" <sip:1000009@80.239.107.66:48186>
Call-ID: 8E2D63AB0E714B5AA81AFAC17AB10400@BRIIZ.NO
CSeq: 28815 REGISTER
Expires: 60
Max-Forwards: 70
User-Agent: X-PRO release 1103g
Content-Length: 0


11 headers, 0 lines
Using latest request as basis request
Sending to 80.239.107.66 : 48186 (NAT)
Transmitting (NAT):
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 80.239.107.66:48186;branch=z9hG4bK5590A407ADDE483F9C8E4F866DF0934A;received=80.239.107.66;rport=48186
From: Atle Nygaard <sip:1000009@BRIIZ.NO:1025>;tag=734148128
To: Atle Nygaard <sip:1000009@BRIIZ.NO:1025>;tag=as51289661
Call-ID: 8E2D63AB0E714B5AA81AFAC17AB10400@BRIIZ.NO
CSeq: 28815 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER
Contact: <sip:1000009@213.160.242.5>
Content-Length: 0


to 80.239.107.66:48186
Transmitting (NAT):
SIP/2.0 401 Unauthorized
Via: SIP/2.0/UDP 80.239.107.66:48186;branch=z9hG4bK5590A407ADDE483F9C8E4F866DF0934A;received=80.239.107.66;rport=48186
From: Atle Nygaard <sip:1000009@BRIIZ.NO:1025>;tag=734148128
To: Atle Nygaard <sip:1000009@BRIIZ.NO:1025>;tag=as51289661
Call-ID: 8E2D63AB0E714B5AA81AFAC17AB10400@BRIIZ.NO
CSeq: 28815 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER
Contact: <sip:1000009@213.160.242.5>
WWW-Authenticate: Digest realm="asterisk", nonce="5c80cfe1"
Content-Length: 0


to 80.239.107.66:48186
Scheduling destruction of call '8E2D63AB0E714B5AA81AFAC17AB10400@BRIIZ.NO' in 15000 ms
sipgw1*CLI>

Sip read:
REGISTER sip:BRIIZ.NO SIP/2.0
Via: SIP/2.0/UDP 80.239.107.66:48186;rport;branch=z9hG4bK96830C513D5E4D41979AFBA5394EEDF0
From: Atle Nygaard <sip:1000009@BRIIZ.NO:1025>;tag=734148128
To: Atle Nygaard <sip:1000009@BRIIZ.NO:1025>
Contact: "Atle Nygaard" <sip:1000009@80.239.107.66:48186>
Call-ID: 8E2D63AB0E714B5AA81AFAC17AB10400@BRIIZ.NO
CSeq: 28816 REGISTER
Expires: 60
Authorization: Digest username="1000009",realm="asterisk",nonce="5c80cfe1",response="49980ec12118699681e21bc6c6eb8955",uri="sip:BRIIZ.NO"
Max-Forwards: 70
User-Agent: X-PRO release 1103g
Content-Length: 0


12 headers, 0 lines
Using latest request as basis request
Sending to 80.239.107.66 : 48186 (NAT)
Transmitting (NAT):
SIP/2.0 100 Trying
Via: SIP/2.0/UDP 80.239.107.66:48186;branch=z9hG4bK96830C513D5E4D41979AFBA5394EEDF0;received=80.239.107.66;rport=48186
From: Atle Nygaard <sip:1000009@BRIIZ.NO:1025>;tag=734148128
To: Atle Nygaard <sip:1000009@BRIIZ.NO:1025>;tag=as51289661
Call-ID: 8E2D63AB0E714B5AA81AFAC17AB10400@BRIIZ.NO
CSeq: 28816 REGISTER
User-Agent: Asterisk PBX
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER
Contact: <sip:1000009@213.160.242.5>
Content-Length: 0


to 80.239.107.66:48186
Sep 14 15:50:29 NOTICE[1085819824]: sched.c:290 ast_sched_del: Attempted to delete non-existant schedule entry 0!
   -- Registered SIP '1000009' at 80.239.107.66 port 48186 expires 60
   -- Saved useragent "X-PRO release 1103g" for peer 1000009
By: Mark Spencer (markster) 2004-09-14 23:24:25

Are you using anything unusual (e.g. mysql / postgres friends)?
By: Roy Sigurd Karlsbakk (rkarlsba) 2004-09-15 02:10:05

Yes
MySQL friends
By: Olle Johansson (oej) 2004-09-15 03:36:39

Roy, is this a "vanilla" chan_sip or do you use some additional mysql_friends patch?
By: Roy Sigurd Karlsbakk (rkarlsba) 2004-09-15 04:21:45

It's slightly custom, but I just tried to roll back to a vanilla asterisk CVS version with sip friends enabled, and it gives the same error.

roy
By: Mark Spencer (markster) 2004-09-15 09:15:50

Fixed in CVS.  In the future, please mention that you're using MySQL friends earlier!  That definitely made finding the bug easier.