Hi, I am running a build of asterisk@home with asterisk 1.2beta1 and am
trying to diagnose RxFax with a Voip incoming trunk. I am running the
latest spandsp and rxfax with libtiff 3.7.
Switching on debug IU can see the call come in, but after a small time
the fax connection drops and the sending fax (paper doc ) has not moved
in the machine.
I guess it must be dropping in the negotiation prelim stuff.
I do have some rtp stuff about time differences and some stuff about
converting from a slin codec to ulaw and dropped frames, I just dont
know what is significant if anything.
Can someone help me to diagnose why the line is just dropping, I have
included the debug below.
Cheers
Paul.
Oct 17 11:10:24 DEBUG[3088] pbx.c: Launching 'RxFAX'
Oct 17 11:10:24 VERBOSE[3088] logger.c: -- Executing
RxFAX("SIP/6969021653-dc67",
"/var/spool/asterisk/fax/1129540223.28.tif") in new stack
Oct 17 11:10:24 DEBUG[3088] channel.c: Set channel SIP/6969021653-dc67
to read format slin
Oct 17 11:10:24 DEBUG[3088] channel.c: Set channel SIP/6969021653-dc67
to write format slin
Oct 17 11:10:24 NOTICE[3088] channel.c: Dropping incompatible voice
frame on SIP/6969021653-dc67 of format slin since our native format has
changed to ulaw
Oct 17 11:10:27 DEBUG[3088] rtp.c: Difference is 23528, ms is 2961
Oct 17 11:10:30 DEBUG[3088] rtp.c: Difference is 22416, ms is 2822
Oct 17 11:10:31 DEBUG[3088] rtp.c: Difference is 1920, ms is 260
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Allocating new SIP dialog for
13587bb10611325917636b6a211c0182@192.168.0.10 - REGISTER (No RTP)
Oct 17 11:10:35 DEBUG[3088] acl.c: ##### Testing 80.87.16.11 with
192.168.0.0
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Target address 80.87.16.11 is
not local, substituting externip
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Scheduled a registration timeout
for sip.vira.it id #420
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: REGISTER sip:sip.vira.it
SIP/2.0 (32)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: Via: SIP/2.0/UDP
82.106.48.104:5060;branch=z9hG4bK683546c8 (58)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: From:
<sip:6969021653@sip.vira.it>;tag=as0edb555e (49)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: To:
<sip:6969021653@sip.vira.it> (32)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: Call-ID:
13587bb10611325917636b6a211c0182@192.168.0.10 (54)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: CSeq: 104 REGISTER (18)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: User-Agent: Asterisk PBX
(24)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: Authorization: Digest
username="6969021653", realm="asterisk", algorithm=MD5,
uri="sip:sip.vira.it", nonce="3d5b52e3",
response="8fa16c4b34cdbed367257edb0cac9fa1", opaque="" (173)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: Expires: 120 (12)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: Contact:
<sip:6969021653@82.106.48.104> (39)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: Event: registration (19)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: Content-Length: 0 (17)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: (0)
Oct 17 11:10:35 VERBOSE[3088] logger.c: REGISTER attempt 1 to
6969021653@sip.vira.it
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: SIP/2.0 100 Trying (18)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: Via: SIP/2.0/UDP
82.106.48.104:5060;branch=z9hG4bK683546c8;received=82.106.48.104;rport=5060
(92)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: From:
<sip:6969021653@sip.vira.it>;tag=as0edb555e (49)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: To:
<sip:6969021653@sip.vira.it> (32)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: Call-ID:
13587bb10611325917636b6a211c0182@192.168.0.10 (54)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: CSeq: 104 REGISTER (18)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: User-Agent: Asterisk PBX
(24)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: Allow: INVITE, ACK,
CANCEL, OPTIONS, BYE, REFER, NOTIFY (55)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: Contact:
<sip:6969021653@80.87.16.11> (37)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: Content-Length: 0 (17)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: (0)Oct 17 11:10:35
DEBUG[3088] chan_sip.c: (Provisional) Stopping retransmission (but
retaining packet) on '13587bb10611325917636b6a211c0182@192.168.0.10'
Request 104: Found
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: SIP/2.0 401 Unauthorized
(24)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: Via: SIP/2.0/UDP
82.106.48.104:5060;branch=z9hG4bK683546c8;received=82.106.48.104;rport=5060
(92)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: From:
<sip:6969021653@sip.vira.it>;tag=as0edb555e (49)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: To:
<sip:6969021653@sip.vira.it>;tag=as33f90cb4 (47)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: Call-ID:
13587bb10611325917636b6a211c0182@192.168.0.10 (54)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: CSeq: 104 REGISTER (18)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: User-Agent: Asterisk PBX
(24)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: Allow: INVITE, ACK,
CANCEL, OPTIONS, BYE, REFER, NOTIFY (55)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: Contact:
<sip:6969021653@80.87.16.11> (37)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: WWW-Authenticate: Digest
realm="asterisk", nonce="5edc31e9" (60)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: Content-Length: 0 (17)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: (0)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Stopping retransmission on
'13587bb10611325917636b6a211c0182@192.168.0.10' of Request 104: Match
Found
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: REGISTER sip:sip.vira.it
SIP/2.0 (32)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: Via: SIP/2.0/UDP
82.106.48.104:5060;branch=z9hG4bK44514de1 (58)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: From:
<sip:6969021653@sip.vira.it>;tag=as79d19b58 (49)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: To:
<sip:6969021653@sip.vira.it> (32)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: Call-ID:
13587bb10611325917636b6a211c0182@192.168.0.10 (54)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: CSeq: 105 REGISTER (18)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: User-Agent: Asterisk PBX
(24)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: Authorization: Digest
username="6969021653", realm="asterisk", algorithm=MD5,
uri="sip:6969021653@80.87.16.11", nonce="5edc31e9",
response="80bb46652c142fa3ebee7c19572fc678", opaque="" (184)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: Expires: 120 (12)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: Contact:
<sip:6969021653@82.106.48.104> (39)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: Event: registration (19)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: Content-Length: 0 (17)
Oct 17 11:10:35 DEBUG[3088] chan_sip.c: Header: (0)
Oct 17 11:10:35 VERBOSE[3088] logger.c: REGISTER attempt 2 to
6969021653@sip.vira.it
Oct 17 11:10:36 DEBUG[3088] chan_sip.c: Header: SIP/2.0 100 Trying (18)
Oct 17 11:10:36 DEBUG[3088] chan_sip.c: Header: Via: SIP/2.0/UDP
82.106.48.104:5060;branch=z9hG4bK44514de1;received=82.106.48.104;rport=5060
(92)
Oct 17 11:10:36 DEBUG[3088] chan_sip.c: Header: From:
<sip:6969021653@sip.vira.it>;tag=as79d19b58 (49)
Oct 17 11:10:36 DEBUG[3088] chan_sip.c: Header: To:
<sip:6969021653@sip.vira.it> (32)
Oct 17 11:10:36 DEBUG[3088] chan_sip.c: Header: Call-ID:
13587bb10611325917636b6a211c0182@192.168.0.10 (54)
Oct 17 11:10:36 DEBUG[3088] chan_sip.c: Header: CSeq: 105 REGISTER (18)
Oct 17 11:10:36 DEBUG[3088] chan_sip.c: Header: User-Agent: Asterisk PBX
(24)
Oct 17 11:10:36 DEBUG[3088] chan_sip.c: Header: Allow: INVITE, ACK,
CANCEL, OPTIONS, BYE, REFER, NOTIFY (55)
Oct 17 11:10:36 DEBUG[3088] chan_sip.c: Header: Contact:
<sip:6969021653@80.87.16.11> (37)
Oct 17 11:10:36 DEBUG[3088] chan_sip.c: Header: Content-Length: 0 (17)
Oct 17 11:10:36 DEBUG[3088] chan_sip.c: Header: Content-Length: 0 (17)
Oct 17 11:10:36 DEBUG[3088] chan_sip.c: Header: (0)
Oct 17 11:10:36 DEBUG[3088] chan_sip.c: (Provisional) Stopping
retransmission (but retaining packet) on
'13587bb10611325917636b6a211c0182@192.168.0.10' Request 105: Found
Oct 17 11:10:36 DEBUG[3088] chan_sip.c: Header: SIP/2.0 200 OK (14)
Oct 17 11:10:36 DEBUG[3088] chan_sip.c: Header: Via: SIP/2.0/UDP
82.106.48.104:5060;branch=z9hG4bK44514de1;received=82.106.48.104;rport=5060
(92)
Oct 17 11:10:36 DEBUG[3088] chan_sip.c: Header: From:
<sip:6969021653@sip.vira.it>;tag=as79d19b58 (49)
Oct 17 11:10:36 DEBUG[3088] chan_sip.c: Header: To:
<sip:6969021653@sip.vira.it>;tag=as33f90cb4 (47)
Oct 17 11:10:36 DEBUG[3088] chan_sip.c: Header: Call-ID:
13587bb10611325917636b6a211c0182@192.168.0.10 (54)
Oct 17 11:10:36 DEBUG[3088] chan_sip.c: Header: CSeq: 105 REGISTER (18)
Oct 17 11:10:36 DEBUG[3088] chan_sip.c: Header: User-Agent: Asterisk PBX
(24)
Oct 17 11:10:36 DEBUG[3088] chan_sip.c: Header: Allow: INVITE, ACK,
CANCEL, OPTIONS, BYE, REFER, NOTIFY (55)
Oct 17 11:10:36 DEBUG[3088] chan_sip.c: Header: Expires: 120 (12)
Oct 17 11:10:36 DEBUG[3088] chan_sip.c: Header: Contact:
<sip:6969021653@82.106.48.104>;expires=120 (51)
Oct 17 11:10:36 DEBUG[3088] chan_sip.c: Header: Date: Mon, 17 Oct 2005
09:10:36 GMT (35)
Oct 17 11:10:36 DEBUG[3088] chan_sip.c: Header: Content-Length: 0 (17)
Oct 17 11:10:36 DEBUG[3088] chan_sip.c: Header: (0)
Oct 17 11:10:36 DEBUG[3088] chan_sip.c: Stopping retransmission on
'13587bb10611325917636b6a211c0182@192.168.0.10' of Request 105: Match
Found
Oct 17 11:10:36 DEBUG[3088] chan_sip.c: Registration successful
Oct 17 11:10:36 DEBUG[3088] chan_sip.c: Cancelling timeout 420
Oct 17 11:10:39 DEBUG[3088] chan_sip.c: Header: NOTIFY
sip:6969021653@82.106.48.104 SIP/2.0 (43)
Oct 17 11:10:39 DEBUG[3088] chan_sip.c: Header: Via: SIP/2.0/UDP
80.87.16.11:5060;branch=z9hG4bK376c25df;rport (62)
Oct 17 11:10:39 DEBUG[3088] chan_sip.c: Header: From: "asterisk"
<sip:asterisk@80.87.16.11>;tag=as56c254cc (58)
Oct 17 11:10:39 DEBUG[3088] chan_sip.c: Header: To:
<sip:6969021653@82.106.48.104> (34)
Oct 17 11:10:39 DEBUG[3088] chan_sip.c: Header: Contact:
<sip:asterisk@80.87.16.11> (35)
Oct 17 11:10:39 DEBUG[3088] chan_sip.c: Header: Call-ID:
2883a82026c521402cc38b2d629bc046@80.87.16.11 (53)
Oct 17 11:10:39 DEBUG[3088] chan_sip.c: Header: CSeq: 102 NOTIFY (16)
Oct 17 11:10:39 DEBUG[3088] chan_sip.c: Header: User-Agent: Asterisk PBX
(24)
Oct 17 11:10:39 DEBUG[3088] chan_sip.c: Header: Event: message-summary (22)
Oct 17 11:10:39 DEBUG[3088] chan_sip.c: Header: Content-Type:
application/simple-message-summary (48)
Oct 17 11:10:39 DEBUG[3088] chan_sip.c: Header: Content-Length: 43 (18)
Oct 17 11:10:39 DEBUG[3088] chan_sip.c: Header: (0)
Oct 17 11:10:39 DEBUG[3088] chan_sip.c: Line: Messages-Waiting: yes (21)
Oct 17 11:10:39 DEBUG[3088] chan_sip.c: Line: Voice-Message: 4/0 (18)
Oct 17 11:10:39 DEBUG[3088] acl.c: ##### Testing 80.87.16.11 with
192.168.0.0
Oct 17 11:10:39 DEBUG[3088] chan_sip.c: Target address 80.87.16.11 is
not local, substituting externip
Oct 17 11:10:39 DEBUG[3088] chan_sip.c: Allocating new SIP dialog for
2883a82026c521402cc38b2d629bc046@80.87.16.11 - NOTIFY (No RTP)
Oct 17 11:10:39 DEBUG[3088] chan_sip.c: **** Received NOTIFY (4) -
Command in SIP NOTIFY
Oct 17 11:10:51 DEBUG[3088] manager.c: Manager received command
'Command'
Oct 17 11:10:51 DEBUG[3088] manager.c: Manager received command
'Command'
Oct 17 11:11:06 DEBUG[3088] rtp.c: Difference is 280968, ms is 35141
Oct 17 11:11:06 DEBUG[3088] rtp.c: Difference is 928, ms is 136
Oct 17 11:11:07 DEBUG[3088] rtp.c: Difference is 1352, ms is 189
Oct 17 11:11:07 DEBUG[3088] chan_sip.c: Header: BYE
sip:6969021653@82.106.48.104 SIP/2.0 (40)
Oct 17 11:11:07 DEBUG[3088] chan_sip.c: Header: Via: SIP/2.0/UDP
80.87.16.11:5060;branch=z9hG4bK2cefd2b9;rport (62)
Oct 17 11:11:07 DEBUG[3088] chan_sip.c: Header: From: "0332773982"
<sip:0332773982@80.87.16.11>;tag=as4523c108 (62)
Oct 17 11:11:07 DEBUG[3088] chan_sip.c: Header: To:
<sip:6969021653@82.106.48.104>;tag=as776e9680 (49)
Oct 17 11:11:07 DEBUG[3088] chan_sip.c: Header: Contact:
<sip:0332773982@80.87.16.11> (37)
Oct 17 11:11:07 DEBUG[3088] chan_sip.c: Header: Call-ID:
768c7c2759e875b04d81565a1bae64b5@80.87.16.11 (53)
Oct 17 11:11:07 DEBUG[3088] chan_sip.c: Header: CSeq: 103 BYE (13)
Oct 17 11:11:07 DEBUG[3088] chan_sip.c: Header: User-Agent: Asterisk PBX
(24)
Oct 17 11:11:07 DEBUG[3088] chan_sip.c: Header: Content-Length: 0 (17)
Oct 17 11:11:07 DEBUG[3088] chan_sip.c: Header: (0)
Oct 17 11:11:07 DEBUG[3088] chan_sip.c: **** Received BYE (8) - Command
in SIP BYE
Oct 17 11:11:07 DEBUG[3088] app_rxfax.c: Got hangup
Oct 17 11:11:07 DEBUG[3088] channel.c: Set channel SIP/6969021653-dc67
to read format ulaw
Oct 17 11:11:07 DEBUG[3088] channel.c: Set channel SIP/6969021653-dc67
to write format ulaw
Oct 17 11:11:07 DEBUG[3088] app_macro.c: Extension s, priority 3
returned normally even though call was hung up
Oct 17 11:11:07 DEBUG[3088] pbx.c: Extension in_fax, priority 3 returned
normally even though call was hung up
Oct 17 11:11:07 DEBUG[3088] pbx.c: Launching 'System'
Oct 17 11:11:07 VERBOSE[3088] logger.c: -- Executing
System("SIP/6969021653-dc67", "tiff2ps -2eaz -w 8.5 -h 11
/var/spool/asterisk/fax/1129540223.28.tif | ps2pdf -
/var/spool/asterisk/fax/1129540223.28.tif.pdf") in new stack
Oct 17 11:11:07 DEBUG[3088] pbx.c: Launching 'System'
Oct 17 11:11:07 VERBOSE[3088] logger.c: -- Executing
System("SIP/6969021653-dc67", "mime-construct --to asterisk
--subject
"Fax from 0332773982 0332773982" --attachment 0332773982.pdf --type
application/pdf --file /var/spool/asterisk/fax/1129540223.28.tif.pdf")
in new stack
Oct 17 11:11:07 DEBUG[3088] pbx.c: Launching 'System'
Oct 17 11:11:07 VERBOSE[3088] logger.c: -- Executing
System("SIP/6969021653-dc67", "rm
/var/spool/asterisk/fax/1129540223.28.tif
/var/spool/asterisk/fax/1129540223.28.tif.pdf") in new stack
Oct 17 11:11:07 DEBUG[3088] pbx.c: Launching 'Hangup'
Oct 17 11:11:07 VERBOSE[3088] logger.c: -- Executing
Hangup("SIP/6969021653-dc67", "") in new stack
Oct 17 11:11:07 DEBUG[3088] pbx.c: Spawn extension (ext-fax,h,4) exited
non-zero on 'SIP/6969021653-dc67'
Oct 17 11:11:07 DEBUG[3088] cdr_addon_mysql.c: cdr_mysql: inserting a
CDR record.
Oct 17 11:11:07 DEBUG[3088] cdr_addon_mysql.c: cdr_mysql: SQL command as
follows: INSERT INTO cdr
(calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode)
VALUES ('2005-10-17 11:10:23','\"0332773982\"
<0332773982>','0332773982','in_fax','ext-fax',
'SIP/6969021653-dc67','','Hangup','',44,44,'ANSWERED',3,'')
Oct 17 11:11:07 DEBUG[3088] channel.c: Hanging up channel
'SIP/6969021653-dc67'
Oct 17 11:11:07 DEBUG[3088] chan_sip.c: Hangup call SIP/6969021653-dc67,
SIP callid 768c7c2759e875b04d81565a1bae64b5@80.87.16.11)
Oct 17 11:11:07 DEBUG[3088] chan_sip.c: update_user_counter(6969021653)
- decrement inUse counter
Oct 17 11:11:07 DEBUG[3088] devicestate.c: Changing state for
SIP/6969021653 - state 4 (Invalid)
