[Asterisk-Users] fax pass-through

Tue Feb 14 02:29:51 MST 2006

hi,

after upgrade from 1.0.x to 1.2.x i cannot send faxes
my topology:
PSTN<-wct4xxp-asterisk- -sip- ata (ht496,ht488,asus vp100) - samsung 
sf2500 fax

log:
Feb 13 23:50:35 DEBUG[27914] chan_sip.c: Allocating new SIP dialog for 
20d700003cb20000 at 192.168.1.209 - INVITE (With RTP)
Feb 13 23:50:35 DEBUG[27914] chan_sip.c: **** Received INVITE (5) - 
Command in SIP INVITE
Feb 13 23:50:35 DEBUG[27914] chan_sip.c: * SIP extension value: 1 for call 
20d700003cb20000 at 192.168.1.209
Feb 13 23:50:35 DEBUG[27914] chan_sip.c: Setting NAT on RTP to 524288
Feb 13 23:50:35 DEBUG[27914] chan_sip.c: **** Received ACK (6) - Command 
in SIP ACK
Feb 13 23:50:35 DEBUG[27914] chan_sip.c: Stopping retransmission on 
'20d700003cb20000 at 192.168.1.209' of Response 3727: Match Found
Feb 13 23:50:35 DEBUG[27914] chan_sip.c: **** Received INVITE (5) - 
Command in SIP INVITE
Feb 13 23:50:35 DEBUG[27914] chan_sip.c: Setting NAT on RTP to 524288
Feb 13 23:50:35 DEBUG[27914] chan_sip.c: Checking SIP call limits for 
device 46
Feb 13 23:50:35 DEBUG[27914] chan_sip.c: Updating call counter for 
incoming call
Feb 13 23:50:35 DEBUG[27914] chan_sip.c: build_route: Contact hop: 
<sip:46 at 192.168.1.209>
Feb 13 23:50:35 DEBUG[27904] chan_sip.c: Checking device state for peer 46
Feb 13 23:50:35 DEBUG[27904] devicestate.c: Changing state for SIP/46 - 
state 2 (In use)
Feb 13 23:50:35 DEBUG[28047] pbx.c: Launching 'Goto'
Feb 13 23:50:35 DEBUG[28048] app_queue.c: Device 'SIP/46' changed to state 
'2' (In use)
Feb 13 23:50:35 VERBOSE[28047] logger.c:     -- Executing 
Goto("SIP/46-62bb", "pstn|54|1") in new stack
Feb 13 23:50:35 VERBOSE[28047] logger.c:     -- Goto (pstn,54,1)
Feb 13 23:50:35 DEBUG[28047] chan_iax2.c: peer: 192.168.9.35, username: 
voip, password: test, context: (null)
Feb 13 23:50:35 VERBOSE[27913] logger.c:     -- Call accepted by 
192.168.9.35 (format g729)
Feb 13 23:50:35 DEBUG[28047] pbx.c: Launching 'Macro'
Feb 13 23:50:35 VERBOSE[28047] logger.c:     -- Executing 
Macro("SIP/46-62bb", "stdial|Zap/g1/54|300|tT") in new stack
Feb 13 23:50:35 DEBUG[28047] pbx.c: Launching 'NoOp'
Feb 13 23:50:35 VERBOSE[28047] logger.c:     -- Executing 
NoOp("SIP/46-62bb", "46") in new stack
Feb 13 23:50:35 DEBUG[28047] pbx.c: Launching 'Dial'
Feb 13 23:50:35 VERBOSE[28047] logger.c:     -- Executing 
Dial("SIP/46-62bb", "Zap/g1/54||tT") in new stack
Feb 13 23:50:35 DEBUG[28047] chan_zap.c: Using channel 1
Feb 13 23:50:35 DEBUG[27904] devicestate.c: Changing state for Zap/1 - 
state 2 (In use)
Feb 13 23:50:35 DEBUG[28047] channel.c: Not copying variable 
STACK-macro-stdial-s-2.
Feb 13 23:50:35 DEBUG[28047] channel.c: Not copying variable MACRO_DEPTH.
Feb 13 23:50:35 DEBUG[28047] channel.c: Not copying variable 
STACK-macro-stdial-s-1.
Feb 13 23:50:35 DEBUG[28047] channel.c: Not copying variable ARG3.
Feb 13 23:50:35 DEBUG[28047] channel.c: Not copying variable ARG2.
Feb 13 23:50:35 DEBUG[28047] channel.c: Not copying variable ARG1.
Feb 13 23:50:35 DEBUG[28047] channel.c: Not copying variable 
MACRO_PRIORITY.
Feb 13 23:50:35 DEBUG[28047] channel.c: Not copying variable 
MACRO_CONTEXT.
Feb 13 23:50:35 DEBUG[28047] channel.c: Not copying variable MACRO_EXTEN.
Feb 13 23:50:35 DEBUG[28047] channel.c: Not copying variable 
STACK-pstn-54-1.
Feb 13 23:50:35 DEBUG[28047] channel.c: Not copying variable 
STACK-from_customers-54-1.
Feb 13 23:50:35 DEBUG[28047] channel.c: Not copying variable SIPCALLID.
Feb 13 23:50:35 DEBUG[28047] channel.c: Not copying variable SIPUSERAGENT.
Feb 13 23:50:35 DEBUG[28047] channel.c: Not copying variable SIPDOMAIN.
Feb 13 23:50:35 DEBUG[28047] channel.c: Not copying variable SIPURI.
Feb 13 23:50:35 DEBUG[28049] app_queue.c: Device 'Zap/1' changed to state 
'2' (In use)
Feb 13 23:50:35 VERBOSE[28047] logger.c:     -- Requested transfer 
capability: 0x00 - SPEECH
Feb 13 23:50:35 VERBOSE[28047] logger.c:     -- Called g1/54
Feb 13 23:50:35 DEBUG[28047] channel.c: Set channel Zap/1-1 to read format 
alaw
Feb 13 23:50:35 DEBUG[28047] channel.c: Set channel SIP/46-62bb to write 
format alaw
Feb 13 23:50:35 DEBUG[28047] channel.c: Set channel SIP/46-62bb to read 
format alaw
Feb 13 23:50:35 DEBUG[28047] channel.c: Set channel Zap/1-1 to write 
format alaw
Feb 13 23:50:35 DEBUG[27904] devicestate.c: Changing state for Zap/1 - 
state 2 (In use)
Feb 13 23:50:35 DEBUG[28050] app_queue.c: Device 'Zap/1' changed to state 
'2' (In use)
Feb 13 23:50:35 DEBUG[28047] rtp.c: Ooh, format changed from unknown to 
alaw
Feb 13 23:50:35 DEBUG[27908] chan_zap.c: Queuing frame from 
PRI_EVENT_PROCEEDING on channel 0/1 span 1
Feb 13 23:50:35 VERBOSE[28047] logger.c:     -- Zap/1-1 is proceeding 
passing it to SIP/46-62bb
Feb 13 23:50:35 DEBUG[28047] rtp.c: RTP NAT: Got audio from other end. Now 
sending to address 213.155.226.151:5004
Feb 13 23:50:36 DEBUG[27908] chan_zap.c: Enabled echo cancellation on 
channel 1
Feb 13 23:50:36 DEBUG[27904] devicestate.c: Changing state for Zap/1 - 
state 6 (Ringing)
Feb 13 23:50:36 VERBOSE[28047] logger.c:     -- Zap/1-1 is ringing
Feb 13 23:50:36 DEBUG[28051] app_queue.c: Device 'Zap/1' changed to state 
'6' (Ringing)
Feb 13 23:50:54 DEBUG[27908] chan_zap.c: Echo cancellation already on
Feb 13 23:50:54 DEBUG[27904] channel.c: Avoiding initial deadlock for 
'Zap/1-1'
Feb 13 23:50:54 VERBOSE[28047] logger.c: << [ TYPE: Control (4) SUBCLASS: 
Answer (4) ] [Zap/1-1]
Feb 13 23:50:54 VERBOSE[28047] logger.c:     -- Zap/1-1 answered 
SIP/46-62bb
Feb 13 23:50:54 DEBUG[28047] channel.c: Set channel SIP/46-62bb to read 
format alaw
Feb 13 23:50:54 DEBUG[28047] channel.c: Set channel Zap/1-1 to write 
format alaw
Feb 13 23:50:54 DEBUG[28047] channel.c: Set channel Zap/1-1 to read format 
alaw
Feb 13 23:50:54 DEBUG[28047] channel.c: Set channel SIP/46-62bb to write 
format alaw
Feb 13 23:50:54 DEBUG[28047] chan_sip.c: sip_answer(SIP/46-62bb)
Feb 13 23:50:54 DEBUG[27904] devicestate.c: Changing state for Zap/1 - 
state 2 (In use)
Feb 13 23:50:54 DEBUG[27904] chan_sip.c: Checking device state for peer 46
Feb 13 23:50:54 DEBUG[27904] devicestate.c: Changing state for SIP/46 - 
state 2 (In use)
Feb 13 23:50:54 DEBUG[28052] app_queue.c: Device 'Zap/1' changed to state 
'2' (In use)
Feb 13 23:50:54 DEBUG[28053] app_queue.c: Device 'SIP/46' changed to state 
'2' (In use)
Feb 13 23:50:54 DEBUG[27914] chan_sip.c: **** Received ACK (6) - Command 
in SIP ACK
Feb 13 23:50:54 DEBUG[27914] chan_sip.c: Stopping retransmission on 
'20d700003cb20000 at 192.168.1.209' of Response 3728: Match Found
Feb 13 23:50:56 DEBUG[27914] chan_sip.c: Allocating new SIP dialog for (No 
Call-ID) - OPTIONS (No RTP)
Feb 13 23:50:56 DEBUG[27914] chan_sip.c: Stopping retransmission on 
'19b7d4d226e0e1134b97362158429920 at 212.71.129.36' of Request 102: Match 
Found
Feb 13 23:50:56 DEBUG[27914] chan_sip.c: Allocating new SIP dialog for 
19b7d4d226e0e1134b97362158429920 at 212.71.129.36 - SIP/2.0 (No RTP)
Feb 13 23:50:56 DEBUG[27914] chan_sip.c: That's odd...  Got a response on 
a call we dont know about. Cseq 102 Cmd SIP/2.0
Feb 13 23:50:58 DEBUG[27914] chan_sip.c: **** Received INVITE (5) - 
Command in SIP INVITE
Feb 13 23:50:58 VERBOSE[27914] logger.c:     -- Music class default 
requested but no musiconhold loaded.
Feb 13 23:50:58 DEBUG[27914] chan_sip.c: **** Received ACK (6) - Command 
in SIP ACK
Feb 13 23:50:58 DEBUG[27914] chan_sip.c: Stopping retransmission on 
'20d700003cb20000 at 192.168.1.209' of Response 3729: Match Found
Feb 13 23:51:53 DEBUG[27914] chan_sip.c: **** Received INVITE (5) - 
Command in SIP INVITE
Feb 13 23:51:53 DEBUG[28047] rtp.c: RTP NAT: Got audio from other end. Now 
sending to address 213.155.226.151:5004
Feb 13 23:51:53 DEBUG[28047] rtp.c: Difference is 436152, ms is 54539
Feb 13 23:51:53 DEBUG[27914] chan_sip.c: **** Received ACK (6) - Command 
in SIP ACK
Feb 13 23:51:53 DEBUG[27914] chan_sip.c: Stopping retransmission on 
'20d700003cb20000 at 192.168.1.209' of Response 3730: Match Found
Feb 13 23:51:56 DEBUG[27914] chan_sip.c: Allocating new SIP dialog for (No 
Call-ID) - OPTIONS (No RTP)
Feb 13 23:51:56 DEBUG[27914] chan_sip.c: Stopping retransmission on 
'5615f3cf27e0b9c301b6d88d706ea82d at 212.71.129.36' of Request 102: Match 
Found
Feb 13 23:51:56 DEBUG[27914] chan_sip.c: Allocating new SIP dialog for 
5615f3cf27e0b9c301b6d88d706ea82d at 212.71.129.36 - SIP/2.0 (No RTP)
Feb 13 23:51:56 DEBUG[27914] chan_sip.c: That's odd...  Got a response on 
a call we dont know about. Cseq 102 Cmd SIP/2.0
Feb 13 23:52:00 DEBUG[27914] chan_sip.c: **** Received BYE (8) - Command 
in SIP BYE
Feb 13 23:52:00 DEBUG[28047] channel.c: Didn't get a frame from channel: 
SIP/46-62bb
Feb 13 23:52:00 DEBUG[28047] channel.c: Bridge stops bridging channels 
SIP/46-62bb and Zap/1-1
Feb 13 23:52:00 DEBUG[28047] channel.c: Hanging up channel 'Zap/1-1'
Feb 13 23:52:00 DEBUG[28047] chan_zap.c: zt_hangup(Zap/1-1)
Feb 13 23:52:00 DEBUG[28047] chan_zap.c: Set option AUDIO MODE, value: 
ON(1) on Zap/1-1
Feb 13 23:52:00 DEBUG[28047] chan_zap.c: Hangup: channel: 1 index = 0, 
normal = 10, callwait = -1, thirdcall = -1
Feb 13 23:52:00 DEBUG[28047] chan_zap.c: Not yet hungup...  Calling hangup 
once with icause, and clearing call
Feb 13 23:52:00 DEBUG[28047] chan_zap.c: disabled echo cancellation on 
channel 1
Feb 13 23:52:00 DEBUG[28047] chan_zap.c: Set option TDD MODE, value: 
OFF(0) on Zap/1-1
Feb 13 23:52:00 DEBUG[28047] chan_zap.c: Updated conferencing on 1, with 0 
conference users
Feb 13 23:52:00 DEBUG[28047] chan_zap.c: Set option AUDIO MODE, value: 
OFF(0) on Zap/1-1
Feb 13 23:52:00 DEBUG[28047] chan_zap.c: disabled echo cancellation on 
channel 1
Feb 13 23:52:00 VERBOSE[28047] logger.c:     -- Hungup 'Zap/1-1'
Feb 13 23:52:00 DEBUG[28047] app_dial.c: Exiting with DIALSTATUS=ANSWER.
Feb 13 23:52:00 DEBUG[28047] app_macro.c: Spawn extension 
(macro-stdial,s,2) exited non-zero on 'SIP/46-62bb' in macro 'stdial'
Feb 13 23:52:00 DEBUG[28047] pbx.c: Spawn extension (macro-stdial,s,2) 
exited non-zero on 'SIP/46-62bb'
Feb 13 23:52:00 DEBUG[27904] devicestate.c: Changing state for Zap/1 - 
state 0 (Unknown)
Feb 13 23:52:00 DEBUG[28054] app_queue.c: Device 'Zap/1' changed to state 
'0' (Unknown)
Feb 13 23:52:00 DEBUG[28047] pbx.c: Function result is '46'
Feb 13 23:52:00 DEBUG[28047] pbx.c: Function result is '46'
Feb 13 23:52:00 DEBUG[28047] pbx.c: Function result is '54'
Feb 13 23:52:00 DEBUG[28047] pbx.c: Function result is 'pstn'
Feb 13 23:52:00 DEBUG[28047] pbx.c: Function result is 'SIP/46-62bb'
Feb 13 23:52:00 DEBUG[28047] pbx.c: Function result is 'Zap/1-1'
Feb 13 23:52:00 DEBUG[28047] pbx.c: Function result is 'Dial'
Feb 13 23:52:00 DEBUG[28047] pbx.c: Function result is 'Zap/g1/54||tT'
Feb 13 23:52:00 DEBUG[28047] pbx.c: Function result is '2006-02-13 
23:50:35'
Feb 13 23:52:00 DEBUG[28047] pbx.c: Function result is '2006-02-13 
23:50:54'
Feb 13 23:52:00 DEBUG[28047] pbx.c: Function result is '2006-02-13 
23:52:00'
Feb 13 23:52:00 DEBUG[28047] pbx.c: Function result is '85'
Feb 13 23:52:00 DEBUG[28047] pbx.c: Function result is '66'
Feb 13 23:52:00 DEBUG[28047] pbx.c: Function result is 'ANSWERED'
Feb 13 23:52:00 DEBUG[28047] pbx.c: Function result is 'DOCUMENTATION'
Feb 13 23:52:00 DEBUG[28047] pbx.c: Function result is '(null)'
Feb 13 23:52:00 DEBUG[28047] pbx.c: Function result is '1139871035.6'
Feb 13 23:52:00 DEBUG[28047] pbx.c: Function result is '(null)'

any ideas?

---------------------------------------
Marek Cervenka
=======================================