I'm having some strange problems getting IAXmodem to send faxes from HylaFAX. I don't think it's Hyla's problem though because no other use of the IAXmodem port seems to work either.
It registers fine with my server (and re-registers every 60 seconds, as requested). However, aside from this registration, nothing ever gets sent out to the server. I've got IAX2 debug running on the Asterisk server, and Wireshark running on the test server, watching for packets on port 4570 (which is the port I'm sending on). I can see registration packets, but nothing else.
I try to send a fax, it seems to try:
[2006-08-01 12:03:38] Hanging Up
[2006-08-01 12:03:42] Hanging Up
[2006-08-01 12:03:47] Dialing '1234'
[2006-08-01 12:04:19] Registration completed successfully.
[2006-08-01 12:04:33] Hanging Up
[2006-08-01 12:04:37] Hanging Up
...but nothing actually happens. No packets get sent to the Asterisk server. Here's the log:
Aug 01 12:04:42.13: [24131]: SESSION BEGIN 000000034 6131234
Aug 01 12:04:42.13: [24131]: HylaFAX (tm) Version 4.2.5
Aug 01 12:04:42.13: [24131]: SEND FAX: JOB 9 DEST 1234 COMMID 000000034 DEVICE '/dev/ttyIAX01' FROM
'Testing <Testing@localhost>' USER root
Aug 01 12:04:42.13: [24131]: STATE CHANGE: RUNNING -> SENDING
Aug 01 12:04:42.13: [24131]: <-- [12:AT+FCLASS=1\r]
Aug 01 12:04:42.14: [24131]: --> [2:OK]
Aug 01 12:04:42.14: [24131]: MODEM set XON/XOFF/FLUSH: input ignored, output disabled
Aug 01 12:04:42.14: [24131]: DIAL 1234
Aug 01 12:04:42.14: [24131]: <-- [9:ATDT1234\r]
Aug 01 12:05:28.00: [24131]: --> [9:NO ANSWER]
Aug 01 12:05:28.00: [24131]: SEND FAILED: JOB 9 DEST 1234 ERR No answer from remote
Aug 01 12:05:28.00: [24131]: <-- [5:ATH0\r]
Aug 01 12:05:28.00: [24131]: --> [2:OK]
Aug 01 12:05:28.00: [24131]: MODEM set DTR OFF
Aug 01 12:05:28.00: [24131]: MODEM set baud rate: 0 baud (flow control unchanged)
Aug 01 12:05:28.00: [24131]: STATE CHANGE: SENDING -> MODEMWAIT (timeout 5)
Aug 01 12:05:28.00: [24131]: SESSION END
There's no firewalls or anything between the two computers - they're even in the same switch. What would cause it to register successfully, then not even try to send a call through? To add to the mystery, it "picks up the phone" when I ring it and sends appropriate fax noises.
Packet sniffing reveals that the only packets leaving the fax server on the port I specified are the registration ones, every minute or so. Hyla tries to send (as you can see) and nothing's happening.
In the meantime, I've put a regular SIP phone into the same context, and that works fine with the numbers I'm sending to in Hylafax (ie dialling '1234' on the phone does the "right thing").
Receiving faxes works fine too - I've been playing with that recently.
....jurgen
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
I would normally think that the CLI should say *something* at least. But if you're sure that iaxmodem isn't communicating at all with the PBX for outbound calling... then in the iaxmodem.c code enable the iax debugging (search for debug and you'll find it), rebuild, reinstall, and then run iaxmodem manually and watch the output to see what it is that's not happening right.
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
The debug output is interesting. It sends a bunch of PINGs to 0.0.0.0:0 for some reason, even though partway through it manages to re-register to 10.10.42.48:4570. Where'd the IP address go? :-)
Are there any other settings you need to know? I'm running a staticly linked 0.1.13. Hm. I just noticed a 0.1.14's out. I'll give that one a go as well, although the changelog doesn't mention anything about this problem.
That's pretty much the entire thing. I only chopped out the initial registration because it was duplicated later on. The PINGs start when HylaFAX tries to dial. I queue a FAX to be sent, and as soon as faxstat says "Sending job 14", the PINGs start up.
Here's the entire thing from when I started iaxmodem to when I killed it after all the PINGs happened (I've x'd out the password and CID number from the very beginning).
I had a bit more of a play with this since yesterday. I hardcoded my server's IP address into the code, and added a few log lines which echoe the server and IAX call string:
The call string is correct - my server is in there fine:
[2006-08-02 15:15:58] Call string is 'iaxmodem01:hyl@f@x@10.10.42.32/1234'
BUT! AHA! Check out the password! Thinking I'm so clever, I set the password to 'hyl@f@x'. The @s in that password cause havoc in the call string, where @ is a delimiter between the password and the server IP. I changed the password to something without @s, and all's well. Problem solved. Or at least worked around. :-)
Lesson learnt: IAX passwords should not contain @ (or : or /, I suppose).
I went back and tried replacing the @s with %40 (URL-encoded @), but that didn't work: registration failed. Is there some way these could be escaped in the iaxmodem code? Because registration works fine, I'd suggest that using @ in a password "should" work okay.
Thanks for all your help with this, and I hope this didn't cause you to bash your head on the wall too hard.
If you would like to refer to this comment somewhere else in this project, copy and paste the following link:
Hi all,
I'm having some strange problems getting IAXmodem to send faxes from HylaFAX. I don't think it's Hyla's problem though because no other use of the IAXmodem port seems to work either.
It registers fine with my server (and re-registers every 60 seconds, as requested). However, aside from this registration, nothing ever gets sent out to the server. I've got IAX2 debug running on the Asterisk server, and Wireshark running on the test server, watching for packets on port 4570 (which is the port I'm sending on). I can see registration packets, but nothing else.
I try to send a fax, it seems to try:
[2006-08-01 12:03:38] Hanging Up
[2006-08-01 12:03:42] Hanging Up
[2006-08-01 12:03:47] Dialing '1234'
[2006-08-01 12:04:19] Registration completed successfully.
[2006-08-01 12:04:33] Hanging Up
[2006-08-01 12:04:37] Hanging Up
...but nothing actually happens. No packets get sent to the Asterisk server. Here's the log:
Aug 01 12:04:42.13: [24131]: SESSION BEGIN 000000034 6131234
Aug 01 12:04:42.13: [24131]: HylaFAX (tm) Version 4.2.5
Aug 01 12:04:42.13: [24131]: SEND FAX: JOB 9 DEST 1234 COMMID 000000034 DEVICE '/dev/ttyIAX01' FROM
'Testing <Testing@localhost>' USER root
Aug 01 12:04:42.13: [24131]: STATE CHANGE: RUNNING -> SENDING
Aug 01 12:04:42.13: [24131]: <-- [12:AT+FCLASS=1\r]
Aug 01 12:04:42.14: [24131]: --> [2:OK]
Aug 01 12:04:42.14: [24131]: MODEM set XON/XOFF/FLUSH: input ignored, output disabled
Aug 01 12:04:42.14: [24131]: DIAL 1234
Aug 01 12:04:42.14: [24131]: <-- [9:ATDT1234\r]
Aug 01 12:05:28.00: [24131]: --> [9:NO ANSWER]
Aug 01 12:05:28.00: [24131]: SEND FAILED: JOB 9 DEST 1234 ERR No answer from remote
Aug 01 12:05:28.00: [24131]: <-- [5:ATH0\r]
Aug 01 12:05:28.00: [24131]: --> [2:OK]
Aug 01 12:05:28.00: [24131]: MODEM set DTR OFF
Aug 01 12:05:28.00: [24131]: MODEM set baud rate: 0 baud (flow control unchanged)
Aug 01 12:05:28.00: [24131]: STATE CHANGE: SENDING -> MODEMWAIT (timeout 5)
Aug 01 12:05:28.00: [24131]: SESSION END
There's no firewalls or anything between the two computers - they're even in the same switch. What would cause it to register successfully, then not even try to send a call through? To add to the mystery, it "picks up the phone" when I ring it and sends appropriate fax noises.
Here's my config file:
device /dev/ttyIAX01
owner uucp:uucp
mode 660
port 4570
refresh 60
server 10.10.42.32
peername iaxmodem01
secret xxxxxxx
cidname IAXmodem
cidnumber 1234567890
codec slinear
Any ideas?
Thanks!
....jurgen
What does the Asterisk CLI say is going on for that call?
Asterisk says absolutely nothing. :-/
Packet sniffing reveals that the only packets leaving the fax server on the port I specified are the registration ones, every minute or so. Hyla tries to send (as you can see) and nothing's happening.
In the meantime, I've put a regular SIP phone into the same context, and that works fine with the numbers I'm sending to in Hylafax (ie dialling '1234' on the phone does the "right thing").
Receiving faxes works fine too - I've been playing with that recently.
....jurgen
I would normally think that the CLI should say *something* at least. But if you're sure that iaxmodem isn't communicating at all with the PBX for outbound calling... then in the iaxmodem.c code enable the iax debugging (search for debug and you'll find it), rebuild, reinstall, and then run iaxmodem manually and watch the output to see what it is that's not happening right.
Thanks for the quick replies!
The debug output is interesting. It sends a bunch of PINGs to 0.0.0.0:0 for some reason, even though partway through it manages to re-register to 10.10.42.48:4570. Where'd the IP address go? :-)
Are there any other settings you need to know? I'm running a staticly linked 0.1.13. Hm. I just noticed a 0.1.14's out. I'll give that one a go as well, although the changelog doesn't mention anything about this problem.
Here's the debug:
[2006-08-01 14:23:57] Hanging Up
[2006-08-01 14:24:02] Dialing '92706499'
Tx-Frame Retry[010] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 00003ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
Tx-Frame Retry[009] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 00003ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 9
Tx-Frame Retry[008] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 00003ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 8
Tx-Frame Retry[007] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 00003ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 7
Tx-Frame Retry[006] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 00003ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 6
Tx-Frame Retry[005] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 00003ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 5
Tx-Frame Retry[010] -- OSeqno: 001 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 10003ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
Tx-Frame Retry[009] -- OSeqno: 001 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 10003ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 9
Tx-Frame Retry[008] -- OSeqno: 001 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 10003ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 8
Tx-Frame Retry[007] -- OSeqno: 001 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 10003ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 7
Tx-Frame Retry[004] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 00003ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 4
Tx-Frame Retry[006] -- OSeqno: 001 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 10003ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 6
Tx-Frame Retry[003] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 00003ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 3
Tx-Frame Retry[005] -- OSeqno: 001 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 10003ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 5
Tx-Frame Retry[010] -- OSeqno: 002 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 20007ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
Tx-Frame Retry[009] -- OSeqno: 002 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 20007ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 9
Tx-Frame Retry[008] -- OSeqno: 002 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 20007ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 8
Tx-Frame Retry[002] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 00003ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 2
Tx-Frame Retry[007] -- OSeqno: 002 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 20007ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 7
Tx-Frame Retry[004] -- OSeqno: 001 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 10003ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 4
Tx-Frame Retry[006] -- OSeqno: 002 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 20007ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 6
Tx-Frame Retry[001] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 00003ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 1
Tx-Frame Retry[003] -- OSeqno: 001 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 10003ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 3
Tx-Frame Retry[005] -- OSeqno: 002 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 20007ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 5
Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 00003ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 0
Tx-Frame Retry[010] -- OSeqno: 003 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 30011ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
Tx-Frame Retry[009] -- OSeqno: 003 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 30011ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 9
Tx-Frame Retry[008] -- OSeqno: 003 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 30011ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 8
Tx-Frame Retry[002] -- OSeqno: 001 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 10003ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 2
Tx-Frame Retry[007] -- OSeqno: 003 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 30011ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 7
Tx-Frame Retry[004] -- OSeqno: 002 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 20007ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 4
Tx-Frame Retry[006] -- OSeqno: 003 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 30011ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 6
Tx-Frame Retry[001] -- OSeqno: 001 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 10003ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 1
Tx-Frame Retry[003] -- OSeqno: 002 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 20007ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 3
Tx-Frame Retry[010] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: REGREQ
Timestamp: 00003ms SCall: 23539 DCall: 00000 [10.10.42.32:4569]
USERNAME : iaxmodem01
REFRESH : 60
Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: REGAUTH
Timestamp: 00002ms SCall: 00001 DCall: 23539 [10.10.42.32:4569]
AUTHMETHODS : 2
CHALLENGE : 654697610
USERNAME : iaxmodem01
iax.c line 2421 in iax_header_to_event: Cancelling transmission of packet 0
Tx-Frame Retry[010] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: REGREQ
Timestamp: 00002ms SCall: 23539 DCall: 00001 [10.10.42.32:4569]
USERNAME : iaxmodem01
MD5 RESULT : 4614fb5ebf7ca77521e359709a990bb9
REFRESH : 60
Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: REGACK
Timestamp: 00004ms SCall: 00001 DCall: 23539 [10.10.42.32:4569]
USERNAME : iaxmodem01
DATE TIME : 218198804
REFRESH : 60
APPARENT ADDRES : IPV4 10.10.42.48:4570
iax.c line 2421 in iax_header_to_event: Cancelling transmission of packet 1
Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK
Timestamp: 00004ms SCall: 23539 DCall: 00001 [10.10.42.32:4569]
[2006-08-01 14:24:41] Registration completed successfully.
Tx-Frame Retry[005] -- OSeqno: 003 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 30011ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 5
Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 10003ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 0
Tx-Frame Retry[010] -- OSeqno: 004 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 40014ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
Tx-Frame Retry[009] -- OSeqno: 004 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 40014ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 9
Tx-Frame Retry[008] -- OSeqno: 004 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 40014ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 8
Tx-Frame Retry[002] -- OSeqno: 002 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 20007ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 2
Tx-Frame Retry[007] -- OSeqno: 004 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 40014ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 7
Tx-Frame Retry[004] -- OSeqno: 003 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 30011ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 4
Tx-Frame Retry[010] -- OSeqno: 005 ISeqno: 000 Type: IAX Subclass: HANGUP
Timestamp: 43866ms SCall: 23538 DCall: 00000 [0.0.0.0:0]
CAUSE : Give up
Is this when the pings start? I think that I'll need more debug - from the point where things are okay to the point where things go sour.
Something seems not right here. You say that there are other libiax2 libraries on the system?
That's pretty much the entire thing. I only chopped out the initial registration because it was duplicated later on. The PINGs start when HylaFAX tries to dial. I queue a FAX to be sent, and as soon as faxstat says "Sending job 14", the PINGs start up.
Here's the entire thing from when I started iaxmodem to when I killed it after all the PINGs happened (I've x'd out the password and CID number from the very beginning).
torrens iaxmodem-0.1.14 # ./iaxmodem ttyIAX01.cfg
[2006-08-01 14:43:08] Modem started
[2006-08-01 14:43:08] Setting device = '/dev/ttyIAX01'
[2006-08-01 14:43:08] Setting owner = 'uucp:uucp'
[2006-08-01 14:43:08] Setting mode = '660'
[2006-08-01 14:43:08] Setting port = 4570
[2006-08-01 14:43:08] Setting refresh = 60
[2006-08-01 14:43:08] Setting server = '10.10.42.32'
[2006-08-01 14:43:08] Setting peername = 'iaxmodem01'
[2006-08-01 14:43:08] Setting secret = 'xxxxxx'
[2006-08-01 14:43:08] Setting cidname = 'Marketcom'
[2006-08-01 14:43:08] Setting cidnumber = 'xxxxxx'
[2006-08-01 14:43:08] Setting codec = slinear
[2006-08-01 14:43:08] Opened pty, slave device: /dev/pts/6
[2006-08-01 14:43:08] Created /dev/ttyIAX01 symbolic link
Tx-Frame Retry[010] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: REGREQ
Timestamp: 00003ms SCall: 27626 DCall: 00000 [10.10.42.32:4569]
USERNAME : iaxmodem01
REFRESH : 60
Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: REGAUTH
Timestamp: 00001ms SCall: 00003 DCall: 27626 [10.10.42.32:4569]
AUTHMETHODS : 2
CHALLENGE : 149170900
USERNAME : iaxmodem01
iax.c line 2421 in iax_header_to_event: Cancelling transmission of packet 0
Tx-Frame Retry[010] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: REGREQ
Timestamp: 00004ms SCall: 27626 DCall: 00003 [10.10.42.32:4569]
USERNAME : iaxmodem01
MD5 RESULT : 51cc92fb7ed0bc9653ee622d8bc7e5ce
REFRESH : 60
Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: REGACK
Timestamp: 00015ms SCall: 00003 DCall: 27626 [10.10.42.32:4569]
USERNAME : iaxmodem01
DATE TIME : 218199396
REFRESH : 60
APPARENT ADDRES : IPV4 10.10.42.48:4570
iax.c line 2421 in iax_header_to_event: Cancelling transmission of packet 1
Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK
Timestamp: 00015ms SCall: 27626 DCall: 00003 [10.10.42.32:4569]
[2006-08-01 14:43:08] Registration completed successfully.
[2006-08-01 14:43:24] Hanging Up
[2006-08-01 14:43:29] Dialing '92706499'
Tx-Frame Retry[010] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 00003ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
Tx-Frame Retry[009] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 00003ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 9
Tx-Frame Retry[008] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 00003ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 8
Tx-Frame Retry[007] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 00003ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 7
Tx-Frame Retry[006] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 00003ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 6
Tx-Frame Retry[005] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 00003ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 5
Tx-Frame Retry[010] -- OSeqno: 001 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 10003ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
Tx-Frame Retry[009] -- OSeqno: 001 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 10003ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 9
Tx-Frame Retry[008] -- OSeqno: 001 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 10003ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 8
Tx-Frame Retry[007] -- OSeqno: 001 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 10003ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 7
Tx-Frame Retry[004] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 00003ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 4
Tx-Frame Retry[006] -- OSeqno: 001 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 10003ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 6
Tx-Frame Retry[003] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 00003ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 3
Tx-Frame Retry[005] -- OSeqno: 001 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 10003ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 5
Tx-Frame Retry[010] -- OSeqno: 002 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 20010ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
Tx-Frame Retry[009] -- OSeqno: 002 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 20010ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 9
Tx-Frame Retry[008] -- OSeqno: 002 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 20010ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 8
Tx-Frame Retry[002] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 00003ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 2
Tx-Frame Retry[007] -- OSeqno: 002 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 20010ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 7
Tx-Frame Retry[004] -- OSeqno: 001 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 10003ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 4
Tx-Frame Retry[006] -- OSeqno: 002 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 20010ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 6
Tx-Frame Retry[001] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 00003ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 1
Tx-Frame Retry[003] -- OSeqno: 001 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 10003ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 3
Tx-Frame Retry[005] -- OSeqno: 002 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 20010ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 5
Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 00003ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 0
Tx-Frame Retry[010] -- OSeqno: 003 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 30014ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
Tx-Frame Retry[009] -- OSeqno: 003 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 30014ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 9
Tx-Frame Retry[008] -- OSeqno: 003 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 30014ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 8
Tx-Frame Retry[002] -- OSeqno: 001 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 10003ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 2
Tx-Frame Retry[007] -- OSeqno: 003 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 30014ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 7
Tx-Frame Retry[004] -- OSeqno: 002 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 20010ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 4
Tx-Frame Retry[010] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: REGREQ
Timestamp: 00003ms SCall: 27628 DCall: 00000 [10.10.42.32:4569]
USERNAME : iaxmodem01
REFRESH : 60
Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: REGAUTH
Timestamp: 00006ms SCall: 00002 DCall: 27628 [10.10.42.32:4569]
AUTHMETHODS : 2
CHALLENGE : 122090038
USERNAME : iaxmodem01
iax.c line 2421 in iax_header_to_event: Cancelling transmission of packet 0
Tx-Frame Retry[010] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: REGREQ
Timestamp: 00002ms SCall: 27628 DCall: 00002 [10.10.42.32:4569]
USERNAME : iaxmodem01
MD5 RESULT : e8f7e9a550ea541948514f53bbc6cfde
REFRESH : 60
Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: REGACK
Timestamp: 00008ms SCall: 00002 DCall: 27628 [10.10.42.32:4569]
USERNAME : iaxmodem01
DATE TIME : 218199426
REFRESH : 60
APPARENT ADDRES : IPV4 10.10.42.48:4570
iax.c line 2421 in iax_header_to_event: Cancelling transmission of packet 1
Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK
Timestamp: 00008ms SCall: 27628 DCall: 00002 [10.10.42.32:4569]
[2006-08-01 14:44:04] Registration completed successfully.
Tx-Frame Retry[006] -- OSeqno: 003 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 30014ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 6
Tx-Frame Retry[001] -- OSeqno: 001 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 10003ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 1
Tx-Frame Retry[003] -- OSeqno: 002 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 20010ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 3
Tx-Frame Retry[005] -- OSeqno: 003 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 30014ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 5
Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 10003ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 0
Tx-Frame Retry[010] -- OSeqno: 004 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 40018ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
Tx-Frame Retry[009] -- OSeqno: 004 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 40018ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 9
Tx-Frame Retry[008] -- OSeqno: 004 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 40018ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 8
Tx-Frame Retry[002] -- OSeqno: 002 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 20010ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 2
Tx-Frame Retry[007] -- OSeqno: 004 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 40018ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 7
Tx-Frame Retry[004] -- OSeqno: 003 ISeqno: 000 Type: IAX Subclass: PING
Timestamp: 30014ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
iax.c line 3046 in iax_get_event: Scheduling retransmission 4
Tx-Frame Retry[010] -- OSeqno: 005 ISeqno: 000 Type: IAX Subclass: HANGUP
Timestamp: 43858ms SCall: 27627 DCall: 00000 [0.0.0.0:0]
CAUSE : Give up
[2006-08-01 14:44:15] Hanging Up
[2006-08-01 14:44:23] Hanging Up
[2006-08-01 14:44:31] Terminating...
Tx-Frame Retry[010] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: REGREL
Timestamp: 00003ms SCall: 27629 DCall: 00000 [10.10.42.32:4569]
USERNAME : iaxmodem01
CAUSE : Exiting
Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: REGAUTH
Timestamp: 00019ms SCall: 00001 DCall: 27629 [10.10.42.32:4569]
AUTHMETHODS : 2
CHALLENGE : 350271982
USERNAME : iaxmodem01
iax.c line 2421 in iax_header_to_event: Cancelling transmission of packet 0
Tx-Frame Retry[010] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: REGREL
Timestamp: 00002ms SCall: 27629 DCall: 00001 [10.10.42.32:4569]
USERNAME : iaxmodem01
MD5 RESULT : b3af8d50fdcaab396d906c3ac3187939
CAUSE : Exiting
Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: REGACK
Timestamp: 00032ms SCall: 00001 DCall: 27629 [10.10.42.32:4569]
USERNAME : iaxmodem01
DATE TIME : 218199439
iax.c line 2421 in iax_header_to_event: Cancelling transmission of packet 1
Tx-Frame Retry[-01] -- OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK
Timestamp: 00032ms SCall: 27629 DCall: 00001 [10.10.42.32:4569]
torrens iaxmodem-0.1.14 #
Oh, and the libraries included with iaxmodem are the only ones on the system, and they're staticly linked in during compilation.
FYI, the same problem happens with 0.1.14.
There were no changes whatsoever to libiax2 in 0.1.14 over 0.1.13.
I had a bit more of a play with this since yesterday. I hardcoded my server's IP address into the code, and added a few log lines which echoe the server and IAX call string:
(line 377 onwards)
case AT_MODEM_CONTROL_CALL:
/* Dialing */
if (modemstate != MODEM_ONHOOK && modemstate != MODEM_OFFHOOK) return -1;
if (!strchr(num, '%')) {
printlog(LOG_INFO, "Dialing '%s'\n", num);
printlog(LOG_INFO, "Server is '%s'\n",server);
session[0] = iax_session_new();
char ich[256];
snprintf(ich, 255, "%s:%s@%s/%s", regpeer, regsecret, "10.10.42.32", num);
printlog(LOG_INFO, "Call string is '%s'\n",ich);
iax_call(session[0], cidnumber, cidname, ich, NULL, 0, codecreq, CODEC_SUPPORT);
modemstate = MODEM_CALLING;
}
break;
The call string is correct - my server is in there fine:
[2006-08-02 15:15:58] Call string is 'iaxmodem01:hyl@f@x@10.10.42.32/1234'
BUT! AHA! Check out the password! Thinking I'm so clever, I set the password to 'hyl@f@x'. The @s in that password cause havoc in the call string, where @ is a delimiter between the password and the server IP. I changed the password to something without @s, and all's well. Problem solved. Or at least worked around. :-)
Lesson learnt: IAX passwords should not contain @ (or : or /, I suppose).
I went back and tried replacing the @s with %40 (URL-encoded @), but that didn't work: registration failed. Is there some way these could be escaped in the iaxmodem code? Because registration works fine, I'd suggest that using @ in a password "should" work okay.
Thanks for all your help with this, and I hope this didn't cause you to bash your head on the wall too hard.
Are "@" and "/" explicitly prohibited by IAX2 protocol? Or are they simply non-function in practice?
I'm wondering if it's a bug in libiax2 or if it's a specific shortcoming in IAX2 more generally.