[Home]

Summary:ASTERISK-12891: [patch] atxfer from PSTN to SIP exten gives "Unexpected control subclass '-1'", legs cannot hear each other
Reporter:Marcelo Rossi (porks)Labels:
Date Opened:2008-10-14 15:47:28Date Closed:2009-01-21 13:06:12.000-0600
Priority:MinorRegression?No
Status:Closed/CompleteComponents:Resources/res_features
Versions:Frequency of
Occurrence
Related
Issues:
Environment:Attachments:( 0) full_20090112182000.txt
( 1) messages_20090112182000.txt
( 2) subclass-1_trace_porks_v1.10_1.4.21.2.diff.txt
( 3) subclass-1_trace_porks_v1.7_1.4.21.2.diff.txt
( 4) subclass-1_trace_porks_v1.8_1.4.21.2.diff.txt
( 5) subclass-1_trace_porks_v1.9_1.4.21.2.diff.txt
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@prisma_interno-abcf,2
[Oct  1 17:15:48] WARNING[25920] res_features.c: builtin_atxfer|2|100|trace subclass '-1' Local/1204@prisma_interno-9a8a,1
[Oct  1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit|1|100|trace subclass '-1' Local/1206@prisma_interno-abcf,2
[Oct  1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit_full|1|100|trace subclass '-1' Local/1206@prisma_interno-abcf,2
[Oct  1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit_full|2|96|trace subclass '-1' Local/1206@prisma_interno-abcf,2
[Oct  1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit_full|2|88|trace subclass '-1' Local/1206@prisma_interno-abcf,2
[Oct  1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit_full|2|78|trace subclass '-1' Local/1206@prisma_interno-abcf,2
[Oct  1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit_full|2|67|trace subclass '-1' Local/1206@prisma_interno-abcf,2
[Oct  1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit_full|2|58|trace subclass '-1' Local/1206@prisma_interno-abcf,2
[Oct  1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit_full|2|50|trace subclass '-1' Local/1206@prisma_interno-abcf,2
[Oct  1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit_full|2|40|trace subclass '-1' Local/1206@prisma_interno-abcf,2
[Oct  1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit_full|2|30|trace subclass '-1' Local/1206@prisma_interno-abcf,2
[Oct  1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit_full|2|22|trace subclass '-1' Local/1206@prisma_interno-abcf,2
[Oct  1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit_full|2|12|trace subclass '-1' Local/1206@prisma_interno-abcf,2
[Oct  1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit_full|2|2|trace subclass '-1' Local/1206@prisma_interno-abcf,2
[Oct  1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit_full|2|0|trace subclass '-1' Local/1206@prisma_interno-abcf,2
[Oct  1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit|2|0|trace subclass'-1' Local/1206@prisma_interno-abcf,2
[Oct  1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit|1|100|trace subclass '-1' Local/1204@prisma_interno-9a8a,1
[Oct  1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit_full|1|100|trace subclass '-1' Local/1204@prisma_interno-9a8a,1
[Oct  1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit_full|2|100|trace subclass '-1' Local/1204@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@prisma_interno-9a8a,1
[Oct  1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit_full|2|100|trace subclass '-1' Local/1204@prisma_interno-9a8a,1
[Oct  1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit_full|2|100|trace subclass '-1' Local/1204@prisma_interno-9a8a,1
[Oct  1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit_full|2|100|trace subclass '-1' Local/1204@prisma_interno-9a8a,1
[Oct  1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit_full|2|100|trace subclass '-1' Local/1204@prisma_interno-9a8a,1
[Oct  1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit_full|2|100|trace subclass '-1' Local/1204@prisma_interno-9a8a,1
[Oct  1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit_full|2|100|trace subclass '-1' Local/1204@prisma_interno-9a8a,1
[Oct  1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit_full|2|100|trace subclass '-1' Local/1204@prisma_interno-9a8a,1
[Oct  1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit_full|2|100|trace subclass '-1' Local/1204@prisma_interno-9a8a,1
[Oct  1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit_full|2|100|trace subclass '-1' Local/1204@prisma_interno-9a8a,1
[Oct  1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit_full|2|90|trace subclass '-1' Local/1204@prisma_interno-9a8a,1
[Oct  1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit_full|2|82|trace subclass '-1' Local/1204@prisma_interno-9a8a,1
[Oct  1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit_full|2|72|trace subclass '-1' Local/1204@prisma_interno-9a8a,1
[Oct  1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit_full|2|62|trace subclass '-1' Local/1204@prisma_interno-9a8a,1
[Oct  1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit_full|2|52|trace subclass '-1' Local/1204@prisma_interno-9a8a,1
[Oct  1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit_full|2|44|trace subclass '-1' Local/1204@prisma_interno-9a8a,1
[Oct  1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit_full|2|34|trace subclass '-1' Local/1204@prisma_interno-9a8a,1
[Oct  1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit_full|2|24|trace subclass '-1' Local/1204@prisma_interno-9a8a,1
[Oct  1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit_full|2|16|trace subclass '-1' Local/1204@prisma_interno-9a8a,1
[Oct  1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit_full|2|6|trace subclass '-1' Local/1204@prisma_interno-9a8a,1
[Oct  1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit_full|2|0|trace subclass '-1' Local/1204@prisma_interno-9a8a,1
[Oct  1 17:15:48] WARNING[25920] channel.c: ast_waitfordigit|2|0|trace subclass'-1' Local/1204@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@prisma_interno-0bf5,2
[Oct  1 17:40:12] WARNING[25978] res_features.c: builtin_atxfer|2|100|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:12] WARNING[25978] channel.c: ast_waitfordigit|1|100|trace subclass '-1' Local/1205@prisma_interno-0bf5,2
[Oct  1 17:40:12] WARNING[25978] channel.c: ast_waitfordigit_full|1|100|trace subclass '-1' Local/1205@prisma_interno-0bf5,2
[Oct  1 17:40:12] WARNING[25978] channel.c: ast_waitfordigit_full|2|89|trace subclass '-1' Local/1205@prisma_interno-0bf5,2
[Oct  1 17:40:12] WARNING[25978] channel.c: ast_waitfordigit_full|2|70|trace subclass '-1' Local/1205@prisma_interno-0bf5,2
[Oct  1 17:40:12] WARNING[25978] channel.c: ast_waitfordigit_full|2|51|trace subclass '-1' Local/1205@prisma_interno-0bf5,2
[Oct  1 17:40:12] WARNING[25978] channel.c: ast_waitfordigit_full|2|32|trace subclass '-1' Local/1205@prisma_interno-0bf5,2
[Oct  1 17:40:12] WARNING[25978] channel.c: ast_waitfordigit_full|2|13|trace subclass '-1' Local/1205@prisma_interno-0bf5,2
[Oct  1 17:40:12] WARNING[25978] channel.c: ast_waitfordigit_full|2|0|trace subclass '-1' Local/1205@prisma_interno-0bf5,2
[Oct  1 17:40:12] WARNING[25978] channel.c: ast_waitfordigit|2|0|trace subclass'-1' Local/1205@prisma_interno-0bf5,2
[Oct  1 17:40:12] WARNING[25978] channel.c: ast_waitfordigit|1|100|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:12] WARNING[25978] channel.c: ast_waitfordigit_full|1|100|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:12] WARNING[25978] channel.c: ast_waitfordigit_full|2|0|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:12] WARNING[25978] channel.c: ast_waitfordigit|2|0|trace subclass'-1' Local/1206@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@prisma_interno-e155,1
[Oct  1 17:40:12] WARNING[25978] file.c: ast_waitstream|1|0|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:12] WARNING[25978] file.c: waitstream_core|1|19|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:12] WARNING[25978] channel.c: ast_waitfor|1|19|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:12] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:12] WARNING[25978] file.c: waitstream_core|1|20|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:12] WARNING[25978] channel.c: ast_waitfor|1|20|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:12] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:12] WARNING[25978] file.c: waitstream_core|1|20|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:12] WARNING[25978] channel.c: ast_waitfor|1|20|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:12] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:12] WARNING[25978] file.c: waitstream_core|1|20|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:12] WARNING[25978] channel.c: ast_waitfor|1|20|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] file.c: waitstream_core|1|20|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|20|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] file.c: waitstream_core|1|20|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|20|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] file.c: waitstream_core|1|20|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|20|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] file.c: waitstream_core|1|20|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|20|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] file.c: waitstream_core|1|20|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|20|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] file.c: waitstream_core|1|20|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|20|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] file.c: waitstream_core|1|20|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|20|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] file.c: waitstream_core|1|20|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|20|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] file.c: waitstream_core|1|20|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|20|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] file.c: waitstream_core|1|20|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|20|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] file.c: waitstream_core|1|20|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|20|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] file.c: waitstream_core|1|20|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|20|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] file.c: waitstream_core|1|20|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|20|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|6|trace subclass '-1' Local/1206@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@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] file.c: waitstream_core|1|5|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|5|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|5|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] file.c: waitstream_core|1|5|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|5|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|5|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] file.c: waitstream_core|1|5|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|5|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] file.c: waitstream_core|1|1|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|1|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] file.c: waitstream_core|1|18|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|18|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|12|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] file.c: waitstream_core|1|11|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|11|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|3|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] file.c: waitstream_core|1|3|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|3|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] file.c: waitstream_core|1|20|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|20|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|13|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] file.c: waitstream_core|1|12|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|12|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|2|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] file.c: waitstream_core|1|1|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|1|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] file.c: waitstream_core|1|20|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|20|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|13|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] file.c: waitstream_core|1|13|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|13|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|3|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] file.c: waitstream_core|1|2|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|2|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] file.c: waitstream_core|1|20|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|20|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|12|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] file.c: waitstream_core|1|12|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|12|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|2|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] file.c: waitstream_core|1|1|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|1|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] file.c: waitstream_core|1|17|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|17|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|13|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] file.c: waitstream_core|1|13|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|13|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|3|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] file.c: waitstream_core|1|2|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|1|2|trace subclass '-1' Local/1206@prisma_interno-e155,1
[Oct  1 17:40:13] WARNING[25978] channel.c: ast_waitfor|2|0|trace subclass '-1' Local/1206@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

Comments:By: Marcelo Rossi (porks) 2008-10-14 15:49:54

I DO KNOW I'm using a channel driver not supported officially but I've talked to a few users using Digium cards for the PSTN part and even one of them not using digital boards at all that could actually managed to reproduce this bug and the mute problem. Also, it's not possible to upgrade to 1.6 as it's a production server and it's not mine, but I'd love to hear that it has already been fixed in the latest version of Asterisk :-)
By: Caio Begotti (caio1982) 2008-10-15 18:18:00

Is it ever possible that ASTERISK-10197 is related to this issue?
By: Joshua C. Colp (jcolp) 2008-12-16 10:33:51.000-0600

Please provide complete console output with debug enabled as an attachment on this.
By: Tilghman Lesher (tilghman) 2009-01-09 18:25:12.000-0600

Porks:  can you provide the requested information, please?
By: Marcelo Rossi (porks) 2009-01-13 04:40:52.000-0600

Hi all.
I will post logs of my production server, because I've not a test server right now.

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

extensions.conf is:

[from-pstn]
exten => _9999, 1, GoTo(prisma_pstn,s,1)

[prisma-pstn]
exten => s,1,Answer()
exten => s,2,NoOp(${CALLERID(num)})
exten => s,3,NoOp(SIP/1216,5,tT)
exten => s,4,Queue(prisma_atend,tT,,,30)

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

the queue "prisma_atend" has the members:
"SIP/1205"
"SIP/1209"
"SIP/1216"

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

'1198846880' external cellphone calling my asterisk
'192.168.2.51' is the internal ip address of my asterisk
'189.200.200.12' my the external ip address, that is nated for my asterisk

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

In the attachment I made four calls.
The first without debug enabled, in this call occurs the problem.
The other 3 I enabled the debug, but only in the last call the problem occurs.
By: Russell Bryant (russell) 2009-01-21 13:04:41.000-0600

It is clear through your logs that you are using a third-party channel driver.  We can only help you if you are reporting an issue that occurs with unmodified code.
By: Leif Madsen (lmadsen) 2009-01-21 13:06:11.000-0600

Oops... re-closing because I didn't notice this was closed prior to changing of the status.