Hi Guys,
Hope I can get some support here. As I have no clue where to find this…
We have 1 central Asterisk on our HQ, we also have several stores with a server running Asterisk for internal calls.
A couple of these stores have a so-so internetconnection and the IAX2 peer becomes unreachable after a while. (12-24 hours). I have looked in the logs but could not find anything that would have caused this. But what I can see is that once it becomes unreachable, it retries once and goes reachable again then for the 2nd time it goes unreachable it stays that way until we restart Asterisk…
See a small output from the logs:
[Mar 16 16:04:22] VERBOSE[22948] chan_iax2.c: Tx-Frame Retry[-01] – OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK
[Mar 16 16:04:22] VERBOSE[22948] chan_iax2.c: Timestamp: 00010ms SCall: 00647 DCall: 00001 [10.3.30.7:4569]
[Mar 16 16:04:22] DEBUG[22948] chan_iax2.c: schedule decrement of callno used for 10.3.30.7 in 60 seconds
[Mar 16 16:04:22] DEBUG[22948] chan_iax2.c: Peer UADU-2-HQ: got pong, lastms 158, historicms 158, maxms 5000
[Mar 16 16:04:46] VERBOSE[22950] chan_iax2.c: Rx-Frame Retry[ No] – OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE
[Mar 16 16:04:46] VERBOSE[22950] chan_iax2.c: Timestamp: 00003ms SCall: 02613 DCall: 00000 [10.3.30.7:4569]
[Mar 16 16:04:46] VERBOSE[22950] chan_iax2.c:
[Mar 16 16:04:46] VERBOSE[22950] chan_iax2.c: Tx-Frame Retry[ No] – OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG
[Mar 16 16:04:46] VERBOSE[22950] chan_iax2.c: Timestamp: 00003ms SCall: 00001 DCall: 02613 [10.3.30.7:4569]
[Mar 16 16:04:46] VERBOSE[22951] chan_iax2.c: Rx-Frame Retry[ No] – OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK
[Mar 16 16:04:46] VERBOSE[22951] chan_iax2.c: Timestamp: 00003ms SCall: 02613 DCall: 00001 [10.3.30.7:4569]
[Mar 16 16:05:13] DEBUG[22959] chan_sip.c: Allocating new SIP dialog for 02c786747fab2a2b0503e8ee418c9177@127.0.0.1:5060 - OPTIONS (No RTP)
[Mar 16 16:05:13] DEBUG[22959] acl.c: For destination ‘172.16.197.75’, our source address is ‘172.16.197.254’.
[Mar 16 16:05:13] DEBUG[22959] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 172.16.197.254:5060
[Mar 16 16:05:13] DEBUG[22959] chan_sip.c: SIP call-id changed from ‘02c786747fab2a2b0503e8ee418c9177@127.0.0.1:5060’ to ‘4559f87b051b618b53dfa3aa59c576d1@172.16.197.254:5060’
[Mar 16 16:05:13] DEBUG[22959] chan_sip.c: Initializing initreq for method OPTIONS - callid 4559f87b051b618b53dfa3aa59c576d1@172.16.197.254:5060
[Mar 16 16:05:13] DEBUG[22959] chan_sip.c: Trying to put ‘OPTIONS sip’ onto UDP socket destined for 172.16.197.75:5060
[Mar 16 16:05:13] DEBUG[22959] chan_sip.c: = Looking for Call ID: 4559f87b051b618b53dfa3aa59c576d1@172.16.197.254:5060 (Checking To) --From tag as1ec2744e --To-tag ar0db3655d
[Mar 16 16:05:13] DEBUG[22959] chan_sip.c: Stopping retransmission on ‘4559f87b051b618b53dfa3aa59c576d1@172.16.197.254:5060’ of Request 102: Match Found
[Mar 16 16:05:13] DEBUG[22959] chan_sip.c: Destroying SIP dialog 4559f87b051b618b53dfa3aa59c576d1@172.16.197.254:5060
[Mar 16 16:05:22] DEBUG[22947] chan_iax2.c: ip callno count decremented to 0 for 10.3.30.7
[Mar 16 16:05:22] DEBUG[22952] chan_iax2.c: ip callno count incremented to 1 for 10.3.30.7
[Mar 16 16:05:22] DEBUG[22952] chan_iax2.c: Creating new call structure 8025
[Mar 16 16:05:22] DEBUG[22946] chan_iax2.c: Sending 9 on 8025/0 to 10.3.30.7:4569
[Mar 16 16:05:22] VERBOSE[22946] chan_iax2.c: Tx-Frame Retry[000] – OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE
[Mar 16 16:05:22] VERBOSE[22946] chan_iax2.c: Timestamp: 00009ms SCall: 08025 DCall: 00000 [10.3.30.7:4569]
[Mar 16 16:05:22] VERBOSE[22946] chan_iax2.c:
[Mar 16 16:05:24] DEBUG[22953] chan_iax2.c: Sending 9 on 8025/0 to 10.3.30.7:4569
[Mar 16 16:05:24] VERBOSE[22953] chan_iax2.c: Tx-Frame Retry[001] – OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE
[Mar 16 16:05:24] VERBOSE[22953] chan_iax2.c: Timestamp: 00009ms SCall: 08025 DCall: 00000 [10.3.30.7:4569]
[Mar 16 16:05:24] VERBOSE[22953] chan_iax2.c:
[Mar 16 16:05:26] NOTICE[22954] chan_iax2.c: Peer ‘UADU-2-HQ’ is now UNREACHABLE! Time: 158
[Mar 16 16:05:26] DEBUG[22954] devicestate.c: device ‘IAX2/UADU-2-HQ’ state ‘5’
Log with first unreachable then reachable again:
[Mar 15 11:30:40] NOTICE[17903] chan_iax2.c: Peer ‘UADU-2-HQ’ is now UNREACHABLE! Time: 158
[Mar 15 11:30:40] DEBUG[17903] devicestate.c: device ‘IAX2/UADU-2-HQ’ state ‘5’
[Mar 15 11:30:40] DEBUG[17903] chan_iax2.c: schedule decrement of callno used for 10.3.30.7 in 60 seconds
[Mar 15 11:30:40] DEBUG[17920] app_queue.c: Device ‘IAX2/UADU-2-HQ’ changed to state ‘5’ (Unavailable) but we don’t care because they’re not a member of any queue.
[Mar 15 11:30:43] DEBUG[17910] chan_sip.c: Allocating new SIP dialog for 6677e247182f85b145e459550d34be80@127.0.0.1:5060 - OPTIONS (No RTP)
[Mar 15 11:30:43] DEBUG[17910] acl.c: For destination ‘172.16.197.75’, our source address is ‘172.16.197.254’.
[Mar 15 11:30:43] DEBUG[17910] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 172.16.197.254:5060
[Mar 15 11:30:43] DEBUG[17910] chan_sip.c: SIP call-id changed from ‘6677e247182f85b145e459550d34be80@127.0.0.1:5060’ to ‘2ff6be0d57497b21059d0f4737aaa17e@172.16.197.254:5060’
[Mar 15 11:30:43] DEBUG[17910] chan_sip.c: Initializing initreq for method OPTIONS - callid 2ff6be0d57497b21059d0f4737aaa17e@172.16.197.254:5060
[Mar 15 11:30:43] DEBUG[17910] chan_sip.c: Trying to put ‘OPTIONS sip’ onto UDP socket destined for 172.16.197.75:5060
[Mar 15 11:30:43] DEBUG[17910] chan_sip.c: = Looking for Call ID: 2ff6be0d57497b21059d0f4737aaa17e@172.16.197.254:5060 (Checking To) --From tag as1fb2b872 --To-tag ar0gc3c963
[Mar 15 11:30:43] DEBUG[17910] chan_sip.c: Stopping retransmission on ‘2ff6be0d57497b21059d0f4737aaa17e@172.16.197.254:5060’ of Request 102: Match Found
[Mar 15 11:30:43] DEBUG[17910] chan_sip.c: Destroying SIP dialog 2ff6be0d57497b21059d0f4737aaa17e@172.16.197.254:5060
[Mar 15 11:30:50] DEBUG[17907] chan_iax2.c: ip callno count incremented to 2 for 10.3.30.7
[Mar 15 11:30:50] DEBUG[17907] chan_iax2.c: Creating new call structure 7514
[Mar 15 11:30:50] DEBUG[17897] chan_iax2.c: Sending 4 on 7514/0 to 10.3.30.7:4569
[Mar 15 11:30:50] DEBUG[17908] chan_iax2.c: Received packet 0, (6, 3)
[Mar 15 11:30:50] DEBUG[17908] chan_iax2.c: Cancelling transmission of packet 0
[Mar 15 11:30:50] DEBUG[17908] chan_iax2.c: IAX subclass 3 received
[Mar 15 11:30:50] NOTICE[17908] chan_iax2.c: Peer ‘UADU-2-HQ’ is now REACHABLE! Time: 157
[Mar 15 11:30:50] DEBUG[17908] devicestate.c: device ‘IAX2/UADU-2-HQ’ state ‘1’
Thanks anyway!