[Home]

Summary:ASTERISK-14792: [patch] Hints/extension state random in 1.6.0.15
Reporter:Benny Amorsen (amorsen)Labels:
Date Opened:2009-09-08 10:31:55Date Closed:2009-10-07 13:38:27
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Channels/chan_sip/Subscriptions
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) extensions.conf
( 1) hintbug-asteriskconsole.txt
( 2) hintbug-tcpdump.txt
( 3) hints.conf
( 4) pbx.c.patch
( 5) sip.conf
( 6) sip-phones.conf
Description:I am getting lots of these:

 == Extension Changed 771[Hints] new state Ringing for Notify User 785-000413233e36-1
 == Extension Changed 772[Hints] new state Idle for Notify User 792-00041327d17e-1

The hint extension seems fairly random, and every time it obviously notifies all watchers. The state also seems random. Nothing is happening on the system to explain this behaviour.

The problem appears on the three different production systems temporarily running 1.6.15. My test system with only 4 connected phones does not exhibit the problem, unfortunately.

1.6.13 is fine; I have downgraded back to that for now. 1.6.1.6 is fine too.

I tried reverting these two changes: r205414:r205415 r204753:r204754. No improvement.
Comments:By: Leif Madsen (lmadsen) 2009-09-16 10:45:09

Please provide some information in order to reproduce and debug this issue. This would include information such as: sip debug, sip history, console output, debugging logs, etc...

Thanks!
By: Benny Amorsen (amorsen) 2009-09-18 09:59:42

I am able to reproduce the problem on one of our test systems in 1.6.0.16rc1! I did the following:

a) started asterisk
b) connected to the console with asterisk -rvvvvvvvvvvv
c) made sure the phones were registered, and that both hints for 202 and 204 were correctly in state Idle.
d) Made a call from 204 to 204, but cancelled the call before it was answered
e) Now both phones are stuck in State:InUse&Ringing

I have uploaded a dump of all sip traffic from the time Asterisk was started and till the end of the test, along with the console output from the test. Let me know if you want sip.conf and extensions.conf as well.
By: Leif Madsen (lmadsen) 2009-09-18 12:42:17

Just the relative parts of your extensions.conf and sip.conf could be useful when attempting to reproduce the issue. Thanks!
By: dimitripietro (dimitripietro) 2009-09-24 22:12:52

The problem also exist in 1.6.0.14 but I confirm it does not exist in 1.6.0.13
By: Benny Amorsen (amorsen) 2009-09-28 05:56:38

I caught it in valgring in 1.6.0.16rc1:

==6808== Conditional jump or move depends on uninitialised value(s)
==6808==    at 0x4551B6: ast_devstate_aggregate_result (in /usr/sbin/asterisk)
==6808==    by 0x48C59C: (within /usr/sbin/asterisk)
==6808==    by 0x48C6BB: (within /usr/sbin/asterisk)
==6808==    by 0x492715: (within /usr/sbin/asterisk)
==6808==    by 0x49B9C7: (within /usr/sbin/asterisk)
==6808==    by 0x1B198105: (within /usr/lib64/asterisk/modules/pbx_config.so)
==6808==    by 0x1B19A26A: (within /usr/lib64/asterisk/modules/pbx_config.so)
==6808==    by 0x1B19A3E8: (within /usr/lib64/asterisk/modules/pbx_config.so)
==6808==    by 0x47B430: (within /usr/sbin/asterisk)
==6808==    by 0x47BB93: load_modules (in /usr/sbin/asterisk)
==6808==    by 0x42E413: main (in /usr/sbin/asterisk)

Here are disassemblies around the first two addresses mentioned. I can provide more information if you want it:

0x00000000004551e6 <ast_devstate_aggregate_result+54>: jne    0x455209 <ast_devstate_aggregate_result+89>
0x00000000004551e8 <ast_devstate_aggregate_result+56>: and    $0x1,%edx
0x00000000004551eb <ast_devstate_aggregate_result+59>: mov    $0x5,%al
0x00000000004551ed <ast_devstate_aggregate_result+61>: jne    0x455209 <ast_devstate_aggregate_result+89>
0x00000000004551ef <ast_devstate_aggregate_result+63>: nop
0x00000000004551f0 <ast_devstate_aggregate_result+64>: mov    $0x1,%eax
0x00000000004551f5 <ast_devstate_aggregate_result+69>: retq  



0x000000000048c4e0 <ast_extension_state2+0>: push   %r12
0x000000000048c4e2 <ast_extension_state2+2>: push   %rbp
0x000000000048c4e3 <ast_extension_state2+3>: push   %rbx
0x000000000048c4e4 <ast_extension_state2+4>: sub    $0x70,%rsp
0x000000000048c4e8 <ast_extension_state2+8>: mov    %fs:0x28,%rax



0x000000000048c590 <ast_extension_state2+176>: callq  0x455110 <ast_devstate_aggregate_add>
0x000000000048c595 <ast_extension_state2+181>: mov    %rsp,%rdi
0x000000000048c598 <ast_extension_state2+184>: callq  0x4551b0 <ast_devstate_aggregate_result>
0x000000000048c59d <ast_extension_state2+189>: mov    %eax,%edx
0x000000000048c59f <ast_extension_state2+191>: xor    %eax,%eax
0x000000000048c5a1 <ast_extension_state2+193>: cmp    $0x8,%edx
By: Wolfgang Liegel (wliegel) 2009-10-01 10:42:22

Try adding:
 ast_devstate_aggregate_init(&agg);
into function ast_extension_state2(struct ast_exten *e) in main/pbx.c:3207

I'm not sure if it is the best solution for this problem, but it seems to work.
By: Benny Amorsen (amorsen) 2009-10-06 08:52:39

That solves the problem!
By: Faris Raouf (faris1) 2009-10-06 11:57:47

I can confirm that I had the same sort of problem in 1.6.0.15, and that adding ast_devstate_aggregate_init(&agg);
into function ast_extension_state2(struct ast_exten *e) in main/pbx.c:3207 as suggested by wliegel resolved the problem (and with no obvious side effects).

But just to be clear, in my case I'd describe the problem as hints getting "stuck": If I ring an extension and hang up before it gets answered, the state was Ringing, and stuck there for some time.

If the extension is answered, the state is Ringing/InUse and again gets stuck there for some time.

I can't quantify "some time" I'm afraid.

Anyway, the modification mentioned resolved the issue.

Faris.
By: Leif Madsen (lmadsen) 2009-10-07 09:07:34

Could you please attach the mentioned change as a patch to this issue? That would be the best way of getting this resolved.

Thanks!
By: Wolfgang Liegel (wliegel) 2009-10-07 09:42:19

the patch is now attached to this issue.
Thanks for your support and review.
By: Benny Amorsen (amorsen) 2009-10-07 13:04:45

Oddly enough I can't actually see the patch... I can see in the issue history that it was added, but it seems invisible.
By: Digium Subversion (svnbot) 2009-10-07 13:38:25

Repository: asterisk
Revision: 222605

U   branches/1.6.0/main/pbx.c

------------------------------------------------------------------------
r222605 | seanbright | 2009-10-07 13:38:21 -0500 (Wed, 07 Oct 2009) | 14 lines

Properly initialize ast_devstate_aggregate so we don't crash sporadically.

This looks like it was just missed during a merge.

(closes issue ASTERISK-14780)
Reported by: amorsen
Patches:
     ast_devstate_aggregate_init-in-ast_extension_state2.patch uploaded by amorsen (license 676)
Tested by: amorsen

(closes issue ASTERISK-14792)
Reported by: amorsen
Tested by: amorsen, farisraouf

------------------------------------------------------------------------

http://svn.digium.com/view/asterisk?view=rev&revision=222605