| Summary: | ASTERISK-23992: IAX peering fails without sufficient logging if res_timing_pthread.so is not loaded | ||||
| Reporter: | Hugh Riley (hughriley) | Labels: | |||
| Date Opened: | 2014-07-03 12:36:41 | Date Closed: | 2014-07-03 13:16:48 | ||
| Priority: | Minor | Regression? | |||
| Status: | Closed/Complete | Components: | |||
| Versions: | 11.5.0 11.10.0 | Frequency of Occurrence | Constant | ||
| Related Issues: |
| ||||
| Environment: | Attachments: | ||||
| Description: | Trying to set up multiple Asterisk servers as IAX peers. Unless res_timing_pthread.so is set to load or autoload=yes, IAX2 peers will be marked as UNREACHABLE after a few seconds with no indicator of what the problem might be, even if iax2 debugging is on and core debug is set to 9. As soon as you set autoload=yes or load=res_timing_pthread.so, the servers will peer without a problem.
Logs: Server 1 (with autoload=no and noload=res_timing_pthread.so): console: {noformat} server1*CLI> iax2 set debug peer server2.domain.com IAX2 Debugging Enabled for IP: 192.168.0.2:4569 Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00006ms SCall: 02297 DCall: 00000 [192.168.0.2:4569] Tx-Frame Retry[001] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00006ms SCall: 02297 DCall: 00000 [192.168.0.2:4569] [2014-07-03 12:16:12.506] NOTICE[29060]: chan_iax2.c:12359 __iax2_poke_noanswer: Peer 'server2.domain.com' is now UNREACHABLE! Time: 1 {noformat} -------------------------------------------------------------------------------------------------------------------------------------- debug log: {noformat} [2014-07-03 12:16:08.506] DEBUG[29050] chan_iax2.c: ip callno count decremented to 0 for 192.168.0.2 [2014-07-03 12:16:08.506] DEBUG[29052] chan_iax2.c: ip callno count incremented to 1 for 192.168.0.2 [2014-07-03 12:16:08.506] VERBOSE[29049] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE [2014-07-03 12:16:08.506] VERBOSE[29049] chan_iax2.c: Timestamp: 00006ms SCall: 02297 DCall: 00000 [192.168.0.2:4569] [2014-07-03 12:16:08.506] VERBOSE[29049] chan_iax2.c: [2014-07-03 12:16:09.508] VERBOSE[29056] chan_iax2.c: Tx-Frame Retry[001] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE [2014-07-03 12:16:09.508] VERBOSE[29056] chan_iax2.c: Timestamp: 00006ms SCall: 02297 DCall: 00000 [192.168.0.2:4569] [2014-07-03 12:16:09.508] VERBOSE[29056] chan_iax2.c: [2014-07-03 12:16:12.506] NOTICE[29060] chan_iax2.c: Peer 'server2.domain.com' is now UNREACHABLE! Time: 1 [2014-07-03 12:16:12.506] DEBUG[29060] devicestate.c: device 'IAX2/server2.domain.com' state '5' [2014-07-03 12:16:12.506] DEBUG[29060] chan_iax2.c: schedule decrement of callno used for 192.168.0.2 in 60 seconds {noformat} -------------------------------------------------------------------------------------------------------------------------------------- Server 2 (with autoload=yes): console: {noformat} server2*CLI> iax2 set debug peer server1.domain.com IAX2 Debugging Enabled for IP: 192.168.0.1:4569 Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00006ms SCall: 02297 DCall: 00000 [192.168.0.1:4569] Tx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Timestamp: 00006ms SCall: 00001 DCall: 02297 [192.168.0.1:4569] Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00007ms SCall: 03139 DCall: 00000 [192.168.0.1:4569] Rx-Frame Retry[Yes] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00006ms SCall: 02297 DCall: 00000 [192.168.0.1:4569] Tx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG Timestamp: 00006ms SCall: 00001 DCall: 02297 [192.168.0.1:4569] Tx-Frame Retry[001] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE Timestamp: 00007ms SCall: 03139 DCall: 00000 [192.168.0.1:4569] [2014-07-03 12:16:13.167] NOTICE[5411]: chan_iax2.c:12359 __iax2_poke_noanswer: Peer 'server1.domain.com' is now UNREACHABLE! Time: 1003 {noformat} debug log: {noformat} [2014-07-03 12:16:08.506] VERBOSE[5412] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE [2014-07-03 12:16:08.506] VERBOSE[5412] chan_iax2.c: Timestamp: 00006ms SCall: 02297 DCall: 00000 [192.168.0.1:4569] [2014-07-03 12:16:08.506] VERBOSE[5412] chan_iax2.c: [2014-07-03 12:16:08.506] VERBOSE[5412] chan_iax2.c: Tx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG [2014-07-03 12:16:08.506] VERBOSE[5412] chan_iax2.c: Timestamp: 00006ms SCall: 00001 DCall: 02297 [192.168.0.1:4569] [2014-07-03 12:16:09.167] DEBUG[5416] chan_iax2.c: ip callno count incremented to 2 for 192.168.0.1 [2014-07-03 12:16:09.168] VERBOSE[5405] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE [2014-07-03 12:16:09.168] VERBOSE[5405] chan_iax2.c: Timestamp: 00007ms SCall: 03139 DCall: 00000 [192.168.0.1:4569] [2014-07-03 12:16:09.168] DEBUG[5406] chan_iax2.c: ip callno count decremented to 1 for 192.168.0.1 [2014-07-03 12:16:09.168] VERBOSE[5405] chan_iax2.c: [2014-07-03 12:16:09.508] VERBOSE[5409] chan_iax2.c: Rx-Frame Retry[Yes] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE [2014-07-03 12:16:09.508] VERBOSE[5409] chan_iax2.c: Timestamp: 00006ms SCall: 02297 DCall: 00000 [192.168.0.1:4569] [2014-07-03 12:16:09.508] VERBOSE[5409] chan_iax2.c: [2014-07-03 12:16:09.508] VERBOSE[5409] chan_iax2.c: Tx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG [2014-07-03 12:16:09.508] VERBOSE[5409] chan_iax2.c: Timestamp: 00006ms SCall: 00001 DCall: 02297 [192.168.0.1:4569] [2014-07-03 12:16:10.169] VERBOSE[5410] chan_iax2.c: Tx-Frame Retry[001] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE [2014-07-03 12:16:10.169] VERBOSE[5410] chan_iax2.c: Timestamp: 00007ms SCall: 03139 DCall: 00000 [192.168.0.1:4569] [2014-07-03 12:16:10.169] VERBOSE[5410] chan_iax2.c: [2014-07-03 12:16:13.167] NOTICE[5411] chan_iax2.c: Peer 'server1.domain.com' is now UNREACHABLE! Time: 1003 [2014-07-03 12:16:13.167] DEBUG[5411] devicestate.c: device 'IAX2/server1.domain.com' state '5' [2014-07-03 12:16:13.167] DEBUG[5411] chan_iax2.c: schedule decrement of callno used for 192.168.0.1 in 60 seconds {noformat} | ||||
| Comments: | By: Matt Jordan (mjordan) 2014-07-03 13:16:48.175-0500 This is technically a duplicate of ASTERISK-20963. | ||||