[asterisk-bugs] [Asterisk 0013692]: [patch] atxfer from PSTN to SIP exten gives "Unexpected control subclass '-1'", legs cannot hear each other
Asterisk Bug Tracker
noreply at bugs.digium.com
Wed Jan 21 13:05:18 CST 2009
The following issue has been ASSIGNED.
======================================================================
http://bugs.digium.com/view.php?id=13692
======================================================================
Reported By: Porks
Assigned To: file
======================================================================
Project: Asterisk
Issue ID: 13692
Category: Resources/res_features
Reproducibility: sometimes
Severity: minor
Priority: normal
Status: assigned
Asterisk Version: 1.4.21.2
Regression: No
SVN Branch (only for SVN checkouts, not tarball releases): N/A
SVN Revision (number only!):
Request Review:
======================================================================
Date Submitted: 2008-10-14 15:47 CDT
Last Modified: 2009-01-21 13:05 CST
======================================================================
Summary: [patch] atxfer from PSTN to SIP exten gives
"Unexpected control subclass '-1'", legs cannot hear each other
Description:
Disclaimer: I'd love to provide you access to my production server but it's
my boss's call, not mine. Sorry, you'll need to reproduce it on your own.
The issue is mostly related to two warning messages which fills the log
files and might give hints on the actual problem (the audio stream stops,
thus one leg of the call cannot hear the other side during attended
transfers originated from PSTN):
[Sep 17 16:19:27] WARNING[1436] file.c: Unexpected control subclass '-1'
[Oct 2 11:21:39] WARNING[22939] channel.c: Unexpected control subclass
'-1'
After some deep investigation I've noticed these messages shows up only
during attended transfers. Here's my current scenario, to give you an idea
on how it could be reproduced. The following extensions are SIP, for what
is worth: Exten1 == 1204, Exten2 == 1205, Exten3 == 1206. The default
context's content for these is:
exten => _XXXX, 1, Dial(SIP/${EXTEN},,tTg)
exten => _XXXX, 2, Congestion(10)
exten => _XXXX, 3, HangUp(0)
1. Exten1(1204) calls Exten2(1205)
2. Exten2(1205) answers Exten(1204) and they talk normally
3. Exten2(1205) does an atxfer to Exten3(1206)
4. Exten3(1206) rings, but Exten2(1205) hangs up before Exten3(1206) is
able to answer the call
5. In less than 1 second (or so) after Exten2(1205) hung up, Exten3(1206)
pick up the call and answer it
That's when I notice the messages "Unexpected control subclass '-1'" in my
Asterisk logs. The steps 4 and 5 are extremely important as it's how I
managed to trigger this bug. Exten2 must hang up the call BEFORE Exten3 is
able to answer it and Exten3 must pick the phone up up to 1 second after
that.
If you're not able to reproduce by following the steps above you can run
'tail -f /var/log/asterisk/messages | grep "subclass '-1'"' and try this:
6. Exten3(1206) does an atxfer back to Exten2(1205)
7. Exten2(1205) rings, but before it's answered Exten3(1206) hangs up
8. In less than 1 second (or so) after Exten3(1206) hanged up,
Exten2(1205) answers
If even with this extra atxfer you're not able to reproduce the problem
you can just stick to it and try it a couple of times more, from steps 3 to
8. The message "Unexpected control subclass '-1'" will eventually show up.
The scenario above is SIP-only there's no side effect or problem, at all
(despite the warning message, which at this point is harmless). However, if
you replace Exten1 from the scenario for a call originated from PSTN, the
PSTN side gets muted from the perspective of the guy doing the transfer. To
make it clearer, you can try the same scenario but calling from PSTN (the
context's content is the same, you just have to add the Answer() as the 1st
priority for obvious reasons). In this case, when PSTN calls in and the
message "Unexpected control subclass '-1'" is seen the SIP extension which
receive the atxfer cannot hear the PSTN side, but the person calling from
PSTN can actually hear the audio stream from the SIP extension.
Additional Information:
Here's what I've tried to do in order to track it down. The patch called
subclass-1_trace_porks_v1.7_1.4.21.2.diff.txt gives you something like this
(when the warning message comes from something called in channel.c):
[Oct 1 17:15:48] WARNING[25920] res_features.c:
builtin_atxfer|1|100|trace subclass '-1' Local/1206 at prisma_interno-abcf,2
[Oct 1 17:15:48] WARNING[25920] res_features.c:
builtin_atxfer|2|100|trace subclass '-1' Local/1204 at prisma_interno-9a8a,1
[Oct 1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit|1|100|trace
subclass '-1' Local/1206 at prisma_interno-abcf,2
[Oct 1 17:15:48] WARNING[25920] channel.c:
ast_waitfordigit_full|1|100|trace subclass '-1'
Local/1206 at prisma_interno-abcf,2
[Oct 1 17:15:48] WARNING[25920] channel.c:
ast_waitfordigit_full|2|96|trace subclass '-1'
Local/1206 at prisma_interno-abcf,2
[Oct 1 17:15:48] WARNING[25920] channel.c:
ast_waitfordigit_full|2|88|trace subclass '-1'
Local/1206 at prisma_interno-abcf,2
[Oct 1 17:15:48] WARNING[25920] channel.c:
ast_waitfordigit_full|2|78|trace subclass '-1'
Local/1206 at prisma_interno-abcf,2
[Oct 1 17:15:48] WARNING[25920] channel.c:
ast_waitfordigit_full|2|67|trace subclass '-1'
Local/1206 at prisma_interno-abcf,2
[Oct 1 17:15:48] WARNING[25920] channel.c:
ast_waitfordigit_full|2|58|trace subclass '-1'
Local/1206 at prisma_interno-abcf,2
[Oct 1 17:15:48] WARNING[25920] channel.c:
ast_waitfordigit_full|2|50|trace subclass '-1'
Local/1206 at prisma_interno-abcf,2
[Oct 1 17:15:48] WARNING[25920] channel.c:
ast_waitfordigit_full|2|40|trace subclass '-1'
Local/1206 at prisma_interno-abcf,2
[Oct 1 17:15:48] WARNING[25920] channel.c:
ast_waitfordigit_full|2|30|trace subclass '-1'
Local/1206 at prisma_interno-abcf,2
[Oct 1 17:15:48] WARNING[25920] channel.c:
ast_waitfordigit_full|2|22|trace subclass '-1'
Local/1206 at prisma_interno-abcf,2
[Oct 1 17:15:48] WARNING[25920] channel.c:
ast_waitfordigit_full|2|12|trace subclass '-1'
Local/1206 at prisma_interno-abcf,2
[Oct 1 17:15:48] WARNING[25920] channel.c:
ast_waitfordigit_full|2|2|trace subclass '-1'
Local/1206 at prisma_interno-abcf,2
[Oct 1 17:15:48] WARNING[25920] channel.c:
ast_waitfordigit_full|2|0|trace subclass '-1'
Local/1206 at prisma_interno-abcf,2
[Oct 1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit|2|0|trace
subclass'-1' Local/1206 at prisma_interno-abcf,2
[Oct 1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit|1|100|trace
subclass '-1' Local/1204 at prisma_interno-9a8a,1
[Oct 1 17:15:48] WARNING[25920] channel.c:
ast_waitfordigit_full|1|100|trace subclass '-1'
Local/1204 at prisma_interno-9a8a,1
[Oct 1 17:15:48] WARNING[25920] channel.c:
ast_waitfordigit_full|2|100|trace subclass '-1'
Local/1204 at prisma_interno-9a8a,1
[Oct 1 17:15:48] WARNING[25920] channel.c: Unexpected control subclass
'-1'
[Oct 1 17:15:48] WARNING[25920] channel.c:
ast_waitfordigit_full|3|100|trace subclass '-1'
Local/1204 at prisma_interno-9a8a,1
[Oct 1 17:15:48] WARNING[25920] channel.c:
ast_waitfordigit_full|2|100|trace subclass '-1'
Local/1204 at prisma_interno-9a8a,1
[Oct 1 17:15:48] WARNING[25920] channel.c:
ast_waitfordigit_full|2|100|trace subclass '-1'
Local/1204 at prisma_interno-9a8a,1
[Oct 1 17:15:48] WARNING[25920] channel.c:
ast_waitfordigit_full|2|100|trace subclass '-1'
Local/1204 at prisma_interno-9a8a,1
[Oct 1 17:15:48] WARNING[25920] channel.c:
ast_waitfordigit_full|2|100|trace subclass '-1'
Local/1204 at prisma_interno-9a8a,1
[Oct 1 17:15:48] WARNING[25920] channel.c:
ast_waitfordigit_full|2|100|trace subclass '-1'
Local/1204 at prisma_interno-9a8a,1
[Oct 1 17:15:48] WARNING[25920] channel.c:
ast_waitfordigit_full|2|100|trace subclass '-1'
Local/1204 at prisma_interno-9a8a,1
[Oct 1 17:15:48] WARNING[25920] channel.c:
ast_waitfordigit_full|2|100|trace subclass '-1'
Local/1204 at prisma_interno-9a8a,1
[Oct 1 17:15:48] WARNING[25920] channel.c:
ast_waitfordigit_full|2|100|trace subclass '-1'
Local/1204 at prisma_interno-9a8a,1
[Oct 1 17:15:48] WARNING[25920] channel.c:
ast_waitfordigit_full|2|100|trace subclass '-1'
Local/1204 at prisma_interno-9a8a,1
[Oct 1 17:15:48] WARNING[25920] channel.c:
ast_waitfordigit_full|2|90|trace subclass '-1'
Local/1204 at prisma_interno-9a8a,1
[Oct 1 17:15:48] WARNING[25920] channel.c:
ast_waitfordigit_full|2|82|trace subclass '-1'
Local/1204 at prisma_interno-9a8a,1
[Oct 1 17:15:48] WARNING[25920] channel.c:
ast_waitfordigit_full|2|72|trace subclass '-1'
Local/1204 at prisma_interno-9a8a,1
[Oct 1 17:15:48] WARNING[25920] channel.c:
ast_waitfordigit_full|2|62|trace subclass '-1'
Local/1204 at prisma_interno-9a8a,1
[Oct 1 17:15:48] WARNING[25920] channel.c:
ast_waitfordigit_full|2|52|trace subclass '-1'
Local/1204 at prisma_interno-9a8a,1
[Oct 1 17:15:48] WARNING[25920] channel.c:
ast_waitfordigit_full|2|44|trace subclass '-1'
Local/1204 at prisma_interno-9a8a,1
[Oct 1 17:15:48] WARNING[25920] channel.c:
ast_waitfordigit_full|2|34|trace subclass '-1'
Local/1204 at prisma_interno-9a8a,1
[Oct 1 17:15:48] WARNING[25920] channel.c:
ast_waitfordigit_full|2|24|trace subclass '-1'
Local/1204 at prisma_interno-9a8a,1
[Oct 1 17:15:48] WARNING[25920] channel.c:
ast_waitfordigit_full|2|16|trace subclass '-1'
Local/1204 at prisma_interno-9a8a,1
[Oct 1 17:15:48] WARNING[25920] channel.c:
ast_waitfordigit_full|2|6|trace subclass '-1'
Local/1204 at prisma_interno-9a8a,1
[Oct 1 17:15:48] WARNING[25920] channel.c:
ast_waitfordigit_full|2|0|trace subclass '-1'
Local/1204 at prisma_interno-9a8a,1
[Oct 1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit|2|0|trace
subclass'-1' Local/1204 at prisma_interno-9a8a,1
[Oct 1 17:15:48] WARNING[25920] res_features.c: builtin_atxfer|4|0|trace
subclass '-1'
Around the line 42 of this same patch you will find the function
ast_waitfor_nandfds() which returns with the channel's ast_frame's subclass
equals to -1. By using this same patch, still, you can notice the following
messages (this time triggered by something also called in file.c):
[Oct 1 17:40:12] WARNING[25978] res_features.c:
builtin_atxfer|1|100|trace subclass '-1' Local/1205 at prisma_interno-0bf5,2
[Oct 1 17:40:12] WARNING[25978] res_features.c:
builtin_atxfer|2|100|trace subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:12] WARNING[25978] channel.c: ast_waitfordigit|1|100|trace
subclass '-1' Local/1205 at prisma_interno-0bf5,2
[Oct 1 17:40:12] WARNING[25978] channel.c:
ast_waitfordigit_full|1|100|trace subclass '-1'
Local/1205 at prisma_interno-0bf5,2
[Oct 1 17:40:12] WARNING[25978] channel.c:
ast_waitfordigit_full|2|89|trace subclass '-1'
Local/1205 at prisma_interno-0bf5,2
[Oct 1 17:40:12] WARNING[25978] channel.c:
ast_waitfordigit_full|2|70|trace subclass '-1'
Local/1205 at prisma_interno-0bf5,2
[Oct 1 17:40:12] WARNING[25978] channel.c:
ast_waitfordigit_full|2|51|trace subclass '-1'
Local/1205 at prisma_interno-0bf5,2
[Oct 1 17:40:12] WARNING[25978] channel.c:
ast_waitfordigit_full|2|32|trace subclass '-1'
Local/1205 at prisma_interno-0bf5,2
[Oct 1 17:40:12] WARNING[25978] channel.c:
ast_waitfordigit_full|2|13|trace subclass '-1'
Local/1205 at prisma_interno-0bf5,2
[Oct 1 17:40:12] WARNING[25978] channel.c:
ast_waitfordigit_full|2|0|trace subclass '-1'
Local/1205 at prisma_interno-0bf5,2
[Oct 1 17:40:12] WARNING[25978] channel.c: ast_waitfordigit|2|0|trace
subclass'-1' Local/1205 at prisma_interno-0bf5,2
[Oct 1 17:40:12] WARNING[25978] channel.c: ast_waitfordigit|1|100|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:12] WARNING[25978] channel.c:
ast_waitfordigit_full|1|100|trace subclass '-1'
Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:12] WARNING[25978] channel.c:
ast_waitfordigit_full|2|0|trace subclass '-1'
Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:12] WARNING[25978] channel.c: ast_waitfordigit|2|0|trace
subclass'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:12] WARNING[25978] res_features.c: builtin_atxfer|4|0|trace
subclass '-1'
[Oct 1 17:40:12] WARNING[25978] file.c: ast_stream_and_wait|1|0|trace
subclass'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:12] WARNING[25978] file.c: ast_waitstream|1|0|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:12] WARNING[25978] file.c: waitstream_core|1|19|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:12] WARNING[25978] channel.c: ast_waitfor|1|19|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:12] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:12] WARNING[25978] file.c: waitstream_core|1|20|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:12] WARNING[25978] channel.c: ast_waitfor|1|20|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:12] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:12] WARNING[25978] file.c: waitstream_core|1|20|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:12] WARNING[25978] channel.c: ast_waitfor|1|20|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:12] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:12] WARNING[25978] file.c: waitstream_core|1|20|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:12] WARNING[25978] channel.c: ast_waitfor|1|20|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] file.c: waitstream_core|1|20|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|20|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] file.c: waitstream_core|1|20|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|20|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] file.c: waitstream_core|1|20|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|20|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] file.c: waitstream_core|1|20|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|20|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] file.c: waitstream_core|1|20|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|20|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] file.c: waitstream_core|1|20|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|20|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] file.c: waitstream_core|1|20|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|20|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] file.c: waitstream_core|1|20|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|20|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] file.c: waitstream_core|1|20|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|20|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] file.c: waitstream_core|1|20|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|20|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] file.c: waitstream_core|1|20|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|20|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] file.c: waitstream_core|1|20|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|20|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] file.c: waitstream_core|1|20|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|20|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|6|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] file.c: Unexpected control subclass '-1'
[Oct 1 17:40:13] WARNING[25978] file.c: waitstream_core|4|20|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] file.c: waitstream_core|1|5|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|5|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|5|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] file.c: waitstream_core|1|5|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|5|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|5|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] file.c: waitstream_core|1|5|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|5|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] file.c: waitstream_core|1|1|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|1|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] file.c: waitstream_core|1|18|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|18|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|12|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] file.c: waitstream_core|1|11|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|11|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|3|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] file.c: waitstream_core|1|3|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|3|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] file.c: waitstream_core|1|20|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|20|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|13|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] file.c: waitstream_core|1|12|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|12|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|2|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] file.c: waitstream_core|1|1|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|1|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] file.c: waitstream_core|1|20|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|20|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|13|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] file.c: waitstream_core|1|13|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|13|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|3|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] file.c: waitstream_core|1|2|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|2|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] file.c: waitstream_core|1|20|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|20|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|12|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] file.c: waitstream_core|1|12|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|12|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|2|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] file.c: waitstream_core|1|1|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|1|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] file.c: waitstream_core|1|17|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|17|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|13|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] file.c: waitstream_core|1|13|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|13|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|3|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] file.c: waitstream_core|1|2|trace
subclass '-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|2|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
[Oct 1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass
'-1' Local/1206 at prisma_interno-e155,1
By looking at the output of the patch it seems ast_waitfor_nandfds() has
been called by waitstream_core() around the line 63 of the file
subclass-1_trace_porks_v1.7_1.4.21.2.diff.txt . Anyway, that's still not
the root of all evil, it's only telling me where the problem seems to be
occurring. Look at the logs above again and will see the function
builtin_atxfer(). I've got startled by seeing it there then I wrote the
patch subclass-1_trace_porks_v1.8_1.4.21.2.diff.txt to help me on
debugging.
It should prints the following lines, when the problem is linked to
channel.c again:
[Oct 2 12:22:56] WARNING[6101] res_features.c: builtin_atxfer|0|0|trace
subclass '-1'
[Oct 2 12:22:57] WARNING[6101] res_features.c:
builtin_atxfer|1|1244|trace subclass '-1'
[Oct 2 12:23:03] WARNING[6101] res_features.c:
builtin_atxfer|2|6858|trace subclass '-1'
[Oct 2 12:23:03] WARNING[6101] res_features.c:
builtin_atxfer|4|6860|trace subclass '-1'
[Oct 2 12:23:07] WARNING[6101] res_features.c:
builtin_atxfer|5|10754|trace subclass '-1'
[Oct 2 12:23:07] WARNING[6101] res_features.c:
builtin_atxfer|6|10754|trace subclass '-1'
[Oct 2 12:23:07] WARNING[6101] res_features.c:
builtin_atxfer|7|10754|trace subclass '-1' DGV/3
[Oct 2 12:23:07] WARNING[6101] res_features.c:
builtin_atxfer|8|10754|trace subclass '-1'
[Oct 2 12:23:07] WARNING[6101] res_features.c:
builtin_atxfer|8.1|10754|trace subclass '-1'
[Oct 2 12:23:07] WARNING[6101] channel.c: Unexpected control subclass
'-1'
[Oct 2 12:23:07] WARNING[6101] res_features.c:
builtin_atxfer|9|10965|trace subclass '-1'
[Oct 2 12:23:07] WARNING[6101] res_features.c:
builtin_atxfer|10|10965|trace subclass '-1'
[Oct 2 12:23:07] WARNING[6101] res_features.c:
builtin_atxfer|11|10965|trace subclass '-1'
[Oct 2 12:23:07] WARNING[6101] res_features.c:
builtin_atxfer|12|10965|trace subclass '-1'
[Oct 2 12:23:07] WARNING[6101] res_features.c:
builtin_atxfer|13|10965|trace subclass '-1'
[Oct 2 12:23:07] WARNING[6101] res_features.c:
builtin_atxfer|14|11405|trace subclass '-1'
[Oct 2 12:23:07] WARNING[6101] res_features.c:
builtin_atxfer|15|11405|trace subclass '-1'
When it's linked to file.c this is the output:
[Oct 2 12:24:09] WARNING[6110] res_features.c: builtin_atxfer|0|0|trace
subclass '-1'
[Oct 2 12:24:10] WARNING[6110] res_features.c:
builtin_atxfer|1|1244|trace subclass '-1'
[Oct 2 12:24:15] WARNING[6110] res_features.c:
builtin_atxfer|2|6220|trace subclass '-1'
[Oct 2 12:24:15] WARNING[6110] res_features.c:
builtin_atxfer|4|6222|trace subclass '-1'
[Oct 2 12:24:20] WARNING[6110] res_features.c:
builtin_atxfer|5|11514|trace subclass '-1'
[Oct 2 12:24:20] WARNING[6110] res_features.c:
builtin_atxfer|6|11514|trace subclass '-1'
[Oct 2 12:24:20] WARNING[6110] res_features.c:
builtin_atxfer|7|11514|trace subclass '-1' DGV/4
[Oct 2 12:24:20] WARNING[6110] res_features.c:
builtin_atxfer|8|11514|trace subclass '-1'
[Oct 2 12:24:20] WARNING[6110] res_features.c:
builtin_atxfer|8.1|11514|trace subclass '-1'
[Oct 2 12:24:20] WARNING[6110] res_features.c:
builtin_atxfer|9|11719|trace subclass '-1'
[Oct 2 12:24:20] WARNING[6110] res_features.c:
builtin_atxfer|10|11719|trace subclass '-1'
[Oct 2 12:24:20] WARNING[6110] res_features.c:
builtin_atxfer|11|11719|trace subclass '-1'
[Oct 2 12:24:20] WARNING[6110] res_features.c:
builtin_atxfer|12|11719|trace subclass '-1'
[Oct 2 12:24:20] WARNING[6110] res_features.c:
builtin_atxfer|13|11719|trace subclass '-1'
[Oct 2 12:24:21] WARNING[6110] file.c: Unexpected control subclass '-1'
[Oct 2 12:24:21] WARNING[6110] res_features.c:
builtin_atxfer|14|12159|trace subclass '-1'
[Oct 2 12:24:21] WARNING[6110] res_features.c:
builtin_atxfer|15|12159|trace subclass '-1'
Then I realized that the problem could be occurring when the transferee
answers the call before builtin_atxfer() is over, before it does everything
it's up to. This could explain why it only happens when someone answers the
call too quickly. I started suspecting the issue occurs in channel.c when
the transferee answers the call before the following check is ran: "||
(ast_waitfordigit(newchan, 100) < 0) "
That's inside the if block around the line 77 of the patch
subclass-1_trace_porks_v1.8_1.4.21.2.diff.txt to the .c file. I have also
suspected that the problem occurs in file.c when the transferee answers the
call before builtin_atxfer() is able to execute "if
(ast_stream_and_wait(newchan, xfersound, newchan->language, ""))". That's
around the line 118 of the patch
subclass-1_trace_porks_v1.8_1.4.21.2.diff.txt.
In order to prove this to myself I wrote two more patches to debug it. The
patch subclass-1_trace_porks_v1.9_1.4.21.2.diff.txt just adds a
'usleep(3000000)' between lines 74 and 75 of
subclass-1_trace_porks_v1.8_1.4.21.2.diff.txt. The second one,
subclass-1_trace_porks_v1.10_1.4.21.2.diff.txt, adds a 'usleep(3000000)'
between lines 114 and 115 from
subclass-1_trace_porks_v1.8_1.4.21.2.diff.txt.
With all those information I think it's easier to reproduce and understand
the issue.
Summary:
Apply the patch subclass-1_trace_porks_v1.9_1.4.21.2.diff.txt and you will
see this "subclass '-1'" message more easilly at channel.c
Apply the patch subclass-1_trace_porks_v1.10_1.4.21.2.diff.txt and you
will see this "subclass '-1'" message more easilly at file.c
Asterisk Version: tarball --> 1.4.21.2 AND 1.4.22
======================================================================
Issue History
Date Modified Username Field Change
======================================================================
2009-01-21 13:05 blitzrage Status closed => assigned
======================================================================
More information about the asterisk-bugs
mailing list