[asterisk-users] rxfax Got hangup

[Jan Fousek]

Hi all,
 I'm trying to setup asterisk and spandsp to recieve fax transmissions. I
got Asterisk to detect fax calls, it even tries to communicate, but the
other side doesn't seem to send the main data. Instead it ends the
communication with hangup. Have anybody got an idea? 

Thanks a lot.
Jan Fousek

This is a relevant part of the log:


Jul 18 19:58:30 VERBOSE[20671] logger.c:     -- Executing Answer("SIP/420543254384-b5dd", "") in new stack
Jul 18 19:58:30 VERBOSE[20671] logger.c:     -- Executing AbsoluteTimeout("SIP/420543254384-b5dd", "35") in new stack
Jul 18 19:58:30 VERBOSE[20671] logger.c:     -- Set Absolute Timeout to 35
Jul 18 19:58:30 VERBOSE[20671] logger.c:     -- Executing Set("SIP/420543254384-b5dd", "FAXFILE=/var/spool/asterisk-fax/1153245510.15.tif") in new stack
Jul 18 19:58:30 VERBOSE[20671] logger.c:     -- Executing RxFAX("SIP/420543254384-b5dd", "/var/spool/asterisk-fax/1153245510.15.tif|debug") in new stack
Jul 18 19:58:30 DEBUG[31032] chan_sip.c: Stopping retransmission on 'BW195830538180706-1588437227 at 193.138.78.20' of Response 23395782: Match Found
Jul 18 19:58:32 DEBUG[31032] chan_sip.c: Auto destroying call '75243e2746f654975f4d37b743f9bd7c at 127.0.0.1'
Jul 18 19:58:33 DEBUG[31032] chan_sip.c: Auto destroying call '08623a2019baf62e4ae8d7781e24d8b1 at 127.0.0.1'
Jul 18 19:58:33 DEBUG[20671] app_rxfax.c: FLOW Changed from phase 1 to 4
Jul 18 19:58:33 DEBUG[20671] app_rxfax.c: FLOW >>> DIS:Jul 18 19:58:33 DEBUG[20671] app_rxfax.c:  80Jul 18 19:58:33 DEBUG[20671] app_rxfax.c:  00Jul 18 19:58:33 DEBUG[20671] app_rxfax.c:  ceJul 18 19:58:33 DEBUG[20671] app_rxfax.c:  f4Jul 18 19:58:33 DEBUG[20671] app_rxfax.c:  80Jul 18 19:58:33 DEBUG[20671] app_rxfax.c:  80Jul 18 19:58:33 DEBUG[20671] app_rxfax.c:  81Jul 18 19:58:33 DEBUG[20671] app_rxfax.c:  80Jul 18 19:58:33 DEBUG[20671] app_rxfax.c:  80Jul 18 19:58:33 DEBUG[20671] app_rxfax.c:  80Jul 18 19:58:33 DEBUG[20671] app_rxfax.c:  18Jul 18 19:58:33 DEBUG[20671] app_rxfax.c: 
Jul 18 19:58:35 DEBUG[20671] app_rxfax.c: FLOW HDLC underflow in state 9
Jul 18 19:58:35 DEBUG[20671] app_rxfax.c: FLOW Changed from phase 4 to 3
Jul 18 19:58:36 DEBUG[20671] app_rxfax.c: FLOW HDLC carrier up
Jul 18 19:58:36 DEBUG[20671] app_rxfax.c: FLOW HDLC framing OK
Jul 18 19:58:37 DEBUG[20671] app_rxfax.c: FLOW <<< ???:Jul 18 19:58:37 DEBUG[20671] app_rxfax.c:  1aJul 18 19:58:37 DEBUG[20671] app_rxfax.c: 
Jul 18 19:58:37 DEBUG[20671] app_rxfax.c: FLOW ??? with final frame tag
Jul 18 19:58:37 DEBUG[20671] app_rxfax.c: FLOW In state 9
Jul 18 19:58:37 DEBUG[20671] app_rxfax.c: FLOW HDLC carrier down
Jul 18 19:58:38 DEBUG[20671] app_rxfax.c: FLOW T4 timeout in state 9
Jul 18 19:58:38 DEBUG[20671] app_rxfax.c: FLOW Changed from phase 3 to 4
Jul 18 19:58:38 DEBUG[20671] app_rxfax.c: FLOW >>> DIS:Jul 18 19:58:38 DEBUG[20671] app_rxfax.c:  80Jul 18 19:58:38 DEBUG[20671] app_rxfax.c:  00Jul 18 19:58:38 DEBUG[20671] app_rxfax.c:  ceJul 18 19:58:38 DEBUG[20671] app_rxfax.c:  f4Jul 18 19:58:38 DEBUG[20671] app_rxfax.c:  80Jul 18 19:58:38 DEBUG[20671] app_rxfax.c:  80Jul 18 19:58:38 DEBUG[20671] app_rxfax.c:  81Jul 18 19:58:38 DEBUG[20671] app_rxfax.c:  80Jul 18 19:58:38 DEBUG[20671] app_rxfax.c:  80Jul 18 19:58:38 DEBUG[20671] app_rxfax.c:  80Jul 18 19:58:38 DEBUG[20671] app_rxfax.c:  18Jul 18 19:58:38 DEBUG[20671] app_rxfax.c: 
Jul 18 19:58:40 DEBUG[20671] app_rxfax.c: FLOW HDLC underflow in state 9
Jul 18 19:58:40 DEBUG[20671] app_rxfax.c: FLOW Changed from phase 4 to 3
Jul 18 19:58:43 DEBUG[20671] app_rxfax.c: FLOW T4 timeout in state 9
Jul 18 19:58:43 DEBUG[20671] app_rxfax.c: FLOW Changed from phase 3 to 4
Jul 18 19:58:43 DEBUG[20671] app_rxfax.c: FLOW >>> DIS:Jul 18 19:58:43 DEBUG[20671] app_rxfax.c:  80Jul 18 19:58:43 DEBUG[20671] app_rxfax.c:  00Jul 18 19:58:43 DEBUG[20671] app_rxfax.c:  ceJul 18 19:58:43 DEBUG[20671] app_rxfax.c:  f4Jul 18 19:58:43 DEBUG[20671] app_rxfax.c:  80Jul 18 19:58:43 DEBUG[20671] app_rxfax.c:  80Jul 18 19:58:43 DEBUG[20671] app_rxfax.c:  81Jul 18 19:58:43 DEBUG[20671] app_rxfax.c:  80Jul 18 19:58:43 DEBUG[20671] app_rxfax.c:  80Jul 18 19:58:43 DEBUG[20671] app_rxfax.c:  80Jul 18 19:58:43 DEBUG[20671] app_rxfax.c:  18Jul 18 19:58:43 DEBUG[20671] app_rxfax.c: 
Jul 18 19:58:45 DEBUG[20671] app_rxfax.c: FLOW HDLC underflow in state 9
Jul 18 19:58:45 DEBUG[20671] app_rxfax.c: FLOW Changed from phase 4 to 3
Jul 18 19:58:48 DEBUG[20671] app_rxfax.c: FLOW T4 timeout in state 9
Jul 18 19:58:48 DEBUG[20671] app_rxfax.c: FLOW Changed from phase 3 to 4
Jul 18 19:58:48 DEBUG[20671] app_rxfax.c: FLOW >>> DIS:Jul 18 19:58:48 DEBUG[20671] app_rxfax.c:  80Jul 18 19:58:48 DEBUG[20671] app_rxfax.c:  00Jul 18 19:58:48 DEBUG[20671] app_rxfax.c:  ceJul 18 19:58:48 DEBUG[20671] app_rxfax.c:  f4Jul 18 19:58:48 DEBUG[20671] app_rxfax.c:  80Jul 18 19:58:48 DEBUG[20671] app_rxfax.c:  80Jul 18 19:58:48 DEBUG[20671] app_rxfax.c:  81Jul 18 19:58:48 DEBUG[20671] app_rxfax.c:  80Jul 18 19:58:48 DEBUG[20671] app_rxfax.c:  80Jul 18 19:58:48 DEBUG[20671] app_rxfax.c:  80Jul 18 19:58:48 DEBUG[20671] app_rxfax.c:  18Jul 18 19:58:48 DEBUG[20671] app_rxfax.c: 
Jul 18 19:58:50 DEBUG[20671] app_rxfax.c: FLOW HDLC underflow in state 9
Jul 18 19:58:50 DEBUG[20671] app_rxfax.c: FLOW Changed from phase 4 to 3
Jul 18 19:58:51 DEBUG[20671] app_rxfax.c: FLOW HDLC carrier up
Jul 18 19:58:51 DEBUG[20671] app_rxfax.c: FLOW HDLC framing OK
Jul 18 19:58:52 DEBUG[20671] app_rxfax.c: FLOW <<< ???:Jul 18 19:58:52 DEBUG[20671] app_rxfax.c:  1aJul 18 19:58:52 DEBUG[20671] app_rxfax.c: 
Jul 18 19:58:52 DEBUG[20671] app_rxfax.c: FLOW ??? with final frame tag
Jul 18 19:58:52 DEBUG[20671] app_rxfax.c: FLOW In state 9
Jul 18 19:58:52 DEBUG[20671] app_rxfax.c: FLOW HDLC carrier down
Jul 18 19:58:53 DEBUG[20671] app_rxfax.c: FLOW T4 timeout in state 9
Jul 18 19:58:53 DEBUG[20671] app_rxfax.c: FLOW Changed from phase 3 to 4
Jul 18 19:58:53 DEBUG[20671] app_rxfax.c: FLOW >>> DIS:Jul 18 19:58:53 DEBUG[20671] app_rxfax.c:  80Jul 18 19:58:53 DEBUG[20671] app_rxfax.c:  00Jul 18 19:58:53 DEBUG[20671] app_rxfax.c:  ceJul 18 19:58:53 DEBUG[20671] app_rxfax.c:  f4Jul 18 19:58:53 DEBUG[20671] app_rxfax.c:  80Jul 18 19:58:53 DEBUG[20671] app_rxfax.c:  80Jul 18 19:58:53 DEBUG[20671] app_rxfax.c:  81Jul 18 19:58:53 DEBUG[20671] app_rxfax.c:  80Jul 18 19:58:53 DEBUG[20671] app_rxfax.c:  80Jul 18 19:58:53 DEBUG[20671] app_rxfax.c:  80Jul 18 19:58:53 DEBUG[20671] app_rxfax.c:  18Jul 18 19:58:53 DEBUG[20671] app_rxfax.c: 
Jul 18 19:58:55 DEBUG[20671] app_rxfax.c: FLOW HDLC underflow in state 9
Jul 18 19:58:55 DEBUG[20671] app_rxfax.c: FLOW Changed from phase 4 to 3
Jul 18 19:58:56 DEBUG[20671] app_rxfax.c: FLOW HDLC carrier up
Jul 18 19:58:56 DEBUG[20671] app_rxfax.c: FLOW HDLC framing OK
Jul 18 19:58:58 DEBUG[20671] app_rxfax.c: FLOW <<< ???:Jul 18 19:58:58 DEBUG[20671] app_rxfax.c:  1aJul 18 19:58:58 DEBUG[20671] app_rxfax.c: 
Jul 18 19:58:58 DEBUG[20671] app_rxfax.c: FLOW ??? with final frame tag
Jul 18 19:58:58 DEBUG[20671] app_rxfax.c: FLOW In state 9
Jul 18 19:58:58 DEBUG[20671] app_rxfax.c: FLOW HDLC carrier down
Jul 18 19:58:58 DEBUG[20671] app_rxfax.c: FLOW T4 timeout in state 9
Jul 18 19:58:58 DEBUG[20671] app_rxfax.c: FLOW Changed from phase 3 to 4
Jul 18 19:58:58 DEBUG[20671] app_rxfax.c: FLOW >>> DIS:Jul 18 19:58:58 DEBUG[20671] app_rxfax.c:  80Jul 18 19:58:58 DEBUG[20671] app_rxfax.c:  00Jul 18 19:58:58 DEBUG[20671] app_rxfax.c:  ceJul 18 19:58:58 DEBUG[20671] app_rxfax.c:  f4Jul 18 19:58:58 DEBUG[20671] app_rxfax.c:  80Jul 18 19:58:58 DEBUG[20671] app_rxfax.c:  80Jul 18 19:58:58 DEBUG[20671] app_rxfax.c:  81Jul 18 19:58:58 DEBUG[20671] app_rxfax.c:  80Jul 18 19:58:58 DEBUG[20671] app_rxfax.c:  80Jul 18 19:58:58 DEBUG[20671] app_rxfax.c:  80Jul 18 19:58:58 DEBUG[20671] app_rxfax.c:  18Jul 18 19:58:58 DEBUG[20671] app_rxfax.c: 
Jul 18 19:59:01 DEBUG[20671] app_rxfax.c: FLOW HDLC underflow in state 9
Jul 18 19:59:01 DEBUG[20671] app_rxfax.c: FLOW Changed from phase 4 to 3
Jul 18 19:59:04 DEBUG[20671] app_rxfax.c: FLOW T4 timeout in state 9
Jul 18 19:59:04 DEBUG[20671] app_rxfax.c: FLOW Changed from phase 3 to 4
Jul 18 19:59:04 DEBUG[20671] app_rxfax.c: FLOW >>> DIS:Jul 18 19:59:04 DEBUG[20671] app_rxfax.c:  80Jul 18 19:59:04 DEBUG[20671] app_rxfax.c:  00Jul 18 19:59:04 DEBUG[20671] app_rxfax.c:  ceJul 18 19:59:04 DEBUG[20671] app_rxfax.c:  f4Jul 18 19:59:04 DEBUG[20671] app_rxfax.c:  80Jul 18 19:59:04 DEBUG[20671] app_rxfax.c:  80Jul 18 19:59:04 DEBUG[20671] app_rxfax.c:  81Jul 18 19:59:04 DEBUG[20671] app_rxfax.c:  80Jul 18 19:59:04 DEBUG[20671] app_rxfax.c:  80Jul 18 19:59:04 DEBUG[20671] app_rxfax.c:  80Jul 18 19:59:04 DEBUG[20671] app_rxfax.c:  18Jul 18 19:59:04 DEBUG[20671] app_rxfax.c: 
Jul 18 19:59:05 DEBUG[20671] app_rxfax.c: Got hangup
Jul 18 19:59:05 DEBUG[20671] pbx.c: Extension s, priority 4 returned normally even though call was hung up
Jul 18 19:59:05 DEBUG[20671] pbx.c: Function result is 'unavailable'
Jul 18 19:59:05 DEBUG[20671] pbx.c: Function result is 'unavailable'
Jul 18 19:59:05 DEBUG[20671] pbx.c: Function result is 's'
Jul 18 19:59:05 DEBUG[20671] pbx.c: Function result is 'incomming'
Jul 18 19:59:05 DEBUG[20671] pbx.c: Function result is 'SIP/420543254384-b5dd'
Jul 18 19:59:05 DEBUG[20671] pbx.c: Function result is '(null)'
Jul 18 19:59:05 DEBUG[20671] pbx.c: Function result is 'RxFAX'
Jul 18 19:59:05 DEBUG[20671] pbx.c: Function result is '/var/spool/asterisk-fax/1153245510.15.tif|debug'
Jul 18 19:59:05 DEBUG[20671] pbx.c: Function result is '2006-07-18 19:58:30'
Jul 18 19:59:05 DEBUG[20671] pbx.c: Function result is '2006-07-18 19:58:30'
Jul 18 19:59:05 DEBUG[20671] pbx.c: Function result is '2006-07-18 19:59:05'
Jul 18 19:59:05 DEBUG[20671] pbx.c: Function result is '35'
Jul 18 19:59:05 DEBUG[20671] pbx.c: Function result is '35'
Jul 18 19:59:05 DEBUG[20671] pbx.c: Function result is 'ANSWERED'
Jul 18 19:59:05 DEBUG[20671] pbx.c: Function result is 'DOCUMENTATION'
Jul 18 19:59:05 DEBUG[20671] pbx.c: Function result is '(null)'
Jul 18 19:59:05 DEBUG[20671] pbx.c: Function result is '1153245510.15'
Jul 18 19:59:05 DEBUG[20671] pbx.c: Function result is '(null)'