[Apr 30 16:27:45] NOTICE[5265] cdr.c: CDR simple logging enabled. [Apr 30 16:27:45] NOTICE[5265] loader.c: 188 modules will be loaded. [Apr 30 16:27:45] NOTICE[5265] res_smdi.c: No SMDI interfaces are available to listen on, not starting SMDI listener. [Apr 30 16:27:45] NOTICE[5265] chan_skinny.c: Configuring skinny from skinny.conf [Apr 30 16:27:45] WARNING[5265] chan_dahdi.c: Ignoring any changes to 'userbase' (on reload) at line 23. [Apr 30 16:27:45] WARNING[5265] chan_dahdi.c: Ignoring any changes to 'vmsecret' (on reload) at line 31. [Apr 30 16:27:45] WARNING[5265] chan_dahdi.c: Ignoring any changes to 'hassip' (on reload) at line 35. [Apr 30 16:27:45] WARNING[5265] chan_dahdi.c: Ignoring any changes to 'hasiax' (on reload) at line 39. [Apr 30 16:27:45] WARNING[5265] chan_dahdi.c: Ignoring any changes to 'hasmanager' (on reload) at line 47. [Apr 30 16:27:45] VERBOSE[5265] chan_sip.c: SIP channel loading... [Apr 30 16:27:45] NOTICE[5265] pbx_ael.c: Starting AEL load process. [Apr 30 16:27:45] NOTICE[5265] pbx_ael.c: AEL load process: parsed config file name '/etc/asterisk/extensions.ael'. [Apr 30 16:27:45] NOTICE[5265] pbx_ael.c: AEL load process: checked config file name '/etc/asterisk/extensions.ael'. [Apr 30 16:27:45] NOTICE[5265] pbx_ael.c: AEL load process: compiled config file name '/etc/asterisk/extensions.ael'. [Apr 30 16:27:45] NOTICE[5265] pbx_ael.c: AEL load process: merged config file name '/etc/asterisk/extensions.ael'. [Apr 30 16:27:45] NOTICE[5265] pbx_ael.c: AEL load process: verified config file name '/etc/asterisk/extensions.ael'. [Apr 30 16:27:45] VERBOSE[5265] res_clialiases.c: == Aliased CLI command 'hangup request' to 'channel request hangup' [Apr 30 16:27:45] VERBOSE[5265] res_clialiases.c: == Aliased CLI command 'originate' to 'channel originate' [Apr 30 16:27:45] VERBOSE[5265] res_clialiases.c: == Aliased CLI command 'help' to 'core show help' [Apr 30 16:27:45] VERBOSE[5265] res_clialiases.c: == Aliased CLI command 'pri intense debug span' to 'pri set debug 2 span' [Apr 30 16:27:45] VERBOSE[5265] res_clialiases.c: == Aliased CLI command 'reload' to 'module reload' [Apr 30 16:27:55] VERBOSE[5288] sig_pri.c: == Primary D-Channel on span 1 up [Apr 30 16:27:55] DEBUG[5277] devicestate.c: No provider found, checking channel drivers for DAHDI - I1/congestion [Apr 30 16:27:55] DEBUG[5277] devicestate.c: Changing state for DAHDI/I1/congestion - state 1 (Not in use) [Apr 30 16:27:55] DEBUG[5277] devicestate.c: device 'DAHDI/I1/congestion' state '1' [Apr 30 16:27:55] DEBUG[5313] app_queue.c: Device 'DAHDI/I1/congestion' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 30 16:28:03] VERBOSE[5294] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: NEW [Apr 30 16:28:03] VERBOSE[5294] chan_iax2.c: Timestamp: 00019ms SCall: 16385 DCall: 00000 [88.191.79.104:4569] [Apr 30 16:28:03] VERBOSE[5294] chan_iax2.c: VERSION : 2 [Apr 30 16:28:03] VERBOSE[5294] chan_iax2.c: CALLED NUMBER : 3102 [Apr 30 16:28:03] VERBOSE[5294] chan_iax2.c: CODEC_PREFS : (alaw) [Apr 30 16:28:03] VERBOSE[5294] chan_iax2.c: CALLING NUMBER : 2075 [Apr 30 16:28:03] VERBOSE[5294] chan_iax2.c: CALLING PRESNTN : 0 [Apr 30 16:28:03] VERBOSE[5294] chan_iax2.c: CALLING TYPEOFN : 0 [Apr 30 16:28:03] VERBOSE[5294] chan_iax2.c: CALLING TRANSIT : 0 [Apr 30 16:28:03] VERBOSE[5294] chan_iax2.c: CALLING NAME : Julien Lafont [Apr 30 16:28:03] VERBOSE[5294] chan_iax2.c: LANGUAGE : en [Apr 30 16:28:03] VERBOSE[5294] chan_iax2.c: USERNAME : dediax [Apr 30 16:28:03] VERBOSE[5294] chan_iax2.c: FORMAT : 8 [Apr 30 16:28:03] VERBOSE[5294] chan_iax2.c: CAPABILITY : 1105928 [Apr 30 16:28:03] VERBOSE[5294] chan_iax2.c: ADSICPE : 2 [Apr 30 16:28:03] VERBOSE[5294] chan_iax2.c: DATE TIME : 2012-04-30 16:28:02 [Apr 30 16:28:03] VERBOSE[5294] chan_iax2.c: [Apr 30 16:28:03] DEBUG[5294] chan_iax2.c: Determining if address 88.191.79.104 with username dediax requires calltoken validation. Optional = 1 calltoken_required = 0 [Apr 30 16:28:03] DEBUG[5294] chan_iax2.c: ip callno count incremented to 2 for 88.191.79.104 [Apr 30 16:28:03] DEBUG[5294] chan_iax2.c: Creating new call structure 1236 [Apr 30 16:28:03] DEBUG[5294] chan_iax2.c: Received packet 0, (6, 1) [Apr 30 16:28:03] DEBUG[5294] chan_iax2.c: IAX subclass 1 received [Apr 30 16:28:03] DEBUG[5294] chan_iax2.c: For call=1236, set last=19 [Apr 30 16:28:03] VERBOSE[5294] chan_iax2.c: -- Accepting UNAUTHENTICATED call from 88.191.79.104: > requested format = alaw, > requested prefs = (alaw), > actual format = alaw, > host prefs = (g729|alaw), > priority = mine [Apr 30 16:28:03] DEBUG[5290] chan_iax2.c: Sending 14 on 1236/16385 to 88.191.79.104:4569 [Apr 30 16:28:03] VERBOSE[5290] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: ACCEPT [Apr 30 16:28:03] VERBOSE[5290] chan_iax2.c: Timestamp: 00014ms SCall: 01236 DCall: 16385 [88.191.79.104:4569] [Apr 30 16:28:03] VERBOSE[5290] chan_iax2.c: FORMAT : 8 [Apr 30 16:28:03] VERBOSE[5290] chan_iax2.c: FORMAT2 : alaw [Apr 30 16:28:03] VERBOSE[5290] chan_iax2.c: [Apr 30 16:28:03] VERBOSE[5295] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK [Apr 30 16:28:03] VERBOSE[5295] chan_iax2.c: Timestamp: 00014ms SCall: 16385 DCall: 01236 [88.191.79.104:4569] [Apr 30 16:28:03] DEBUG[5295] chan_iax2.c: Received packet 1, (6, 4) [Apr 30 16:28:03] DEBUG[5295] chan_iax2.c: Cancelling transmission of packet 0 [Apr 30 16:28:03] DEBUG[5295] chan_iax2.c: IAX subclass 4 received [Apr 30 16:28:03] DEBUG[5317] pbx.c: Launching 'Answer' [Apr 30 16:28:03] VERBOSE[5317] pbx.c: -- Executing [3102@dediax:1] Answer("IAX2/dediax-1236", "") in new stack [Apr 30 16:28:03] DEBUG[5317] chan_iax2.c: Answering IAX2 call [Apr 30 16:28:03] DEBUG[5317] chan_iax2.c: Indicating condition -1 [Apr 30 16:28:03] DEBUG[5277] devicestate.c: No provider found, checking channel drivers for IAX2 - dediax [Apr 30 16:28:03] DEBUG[5277] chan_iax2.c: Checking device state for device dediax [Apr 30 16:28:03] DEBUG[5290] chan_iax2.c: Sending 17 on 1236/16385 to 88.191.79.104:4569 [Apr 30 16:28:03] DEBUG[5277] chan_iax2.c: iax2_devicestate: Found peer. What's device state of dediax? addr=1488932712, defaddr=0 maxms=2000, lastms=40 [Apr 30 16:28:03] VERBOSE[5290] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 001 Type: CONTROL Subclass: ANSWER [Apr 30 16:28:03] VERBOSE[5290] chan_iax2.c: Timestamp: 00017ms SCall: 01236 DCall: 16385 [88.191.79.104:4569] [Apr 30 16:28:03] DEBUG[5277] devicestate.c: Changing state for IAX2/dediax - state 2 (In use) [Apr 30 16:28:03] DEBUG[5277] devicestate.c: device 'IAX2/dediax' state '2' [Apr 30 16:28:03] DEBUG[5290] chan_iax2.c: Sending 20 on 1236/16385 to 88.191.79.104:4569 [Apr 30 16:28:03] VERBOSE[5290] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 002 ISeqno: 001 Type: CONTROL Subclass: (255?) [Apr 30 16:28:03] VERBOSE[5290] chan_iax2.c: Timestamp: 00020ms SCall: 01236 DCall: 16385 [88.191.79.104:4569] [Apr 30 16:28:03] DEBUG[5313] app_queue.c: Device 'IAX2/dediax' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Apr 30 16:28:03] VERBOSE[5296] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: ACK [Apr 30 16:28:03] VERBOSE[5296] chan_iax2.c: Timestamp: 00017ms SCall: 16385 DCall: 01236 [88.191.79.104:4569] [Apr 30 16:28:03] DEBUG[5296] chan_iax2.c: Received packet 1, (6, 4) [Apr 30 16:28:03] DEBUG[5296] chan_iax2.c: Cancelling transmission of packet 1 [Apr 30 16:28:03] DEBUG[5296] chan_iax2.c: IAX subclass 4 received [Apr 30 16:28:03] VERBOSE[5296] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 003 Type: IAX Subclass: ACK [Apr 30 16:28:03] VERBOSE[5296] chan_iax2.c: Timestamp: 00020ms SCall: 16385 DCall: 01236 [88.191.79.104:4569] [Apr 30 16:28:03] DEBUG[5296] chan_iax2.c: Received packet 1, (6, 4) [Apr 30 16:28:03] DEBUG[5296] chan_iax2.c: Cancelling transmission of packet 2 [Apr 30 16:28:03] DEBUG[5296] chan_iax2.c: IAX subclass 4 received [Apr 30 16:28:03] VERBOSE[5298] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 003 Type: CONTROL Subclass: SRCUPDT [Apr 30 16:28:03] VERBOSE[5298] chan_iax2.c: Timestamp: 00022ms SCall: 16385 DCall: 01236 [88.191.79.104:4569] [Apr 30 16:28:03] DEBUG[5298] chan_iax2.c: Received packet 1, (4, 20) [Apr 30 16:28:03] DEBUG[5298] chan_iax2.c: Sending 22 on 1236/16385 to 88.191.79.104:4569 [Apr 30 16:28:03] VERBOSE[5298] chan_iax2.c: Tx-Frame Retry[-01] -- OSeqno: 003 ISeqno: 002 Type: IAX Subclass: ACK [Apr 30 16:28:03] VERBOSE[5298] chan_iax2.c: Timestamp: 00022ms SCall: 01236 DCall: 16385 [88.191.79.104:4569] [Apr 30 16:28:03] DEBUG[5298] chan_iax2.c: calc_rxstamp: call=1236: rxcore set to 1335796083.918676 - 22ms [Apr 30 16:28:03] DEBUG[5298] chan_iax2.c: calc_rxstamp: call=1236: works out as 1335796083.896676 [Apr 30 16:28:03] DEBUG[5298] chan_iax2.c: For call=1236, set last=22 [Apr 30 16:28:03] VERBOSE[5299] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: CONTROL Subclass: SRCUPDT [Apr 30 16:28:03] VERBOSE[5299] chan_iax2.c: Timestamp: 00025ms SCall: 16385 DCall: 01236 [88.191.79.104:4569] [Apr 30 16:28:03] DEBUG[5299] chan_iax2.c: Received packet 2, (4, 20) [Apr 30 16:28:03] DEBUG[5299] chan_iax2.c: Sending 25 on 1236/16385 to 88.191.79.104:4569 [Apr 30 16:28:03] VERBOSE[5299] chan_iax2.c: Tx-Frame Retry[-01] -- OSeqno: 003 ISeqno: 003 Type: IAX Subclass: ACK [Apr 30 16:28:03] VERBOSE[5299] chan_iax2.c: Timestamp: 00025ms SCall: 01236 DCall: 16385 [88.191.79.104:4569] [Apr 30 16:28:03] DEBUG[5299] chan_iax2.c: For call=1236, set last=25 [Apr 30 16:28:04] VERBOSE[5292] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 003 Type: VOICE Subclass: 8 [Apr 30 16:28:04] VERBOSE[5292] chan_iax2.c: Timestamp: 00280ms SCall: 16385 DCall: 01236 [88.191.79.104:4569] [Apr 30 16:28:04] DEBUG[5292] chan_iax2.c: Received packet 3, (2, 8) [Apr 30 16:28:04] DEBUG[5292] chan_iax2.c: Ooh, voice format changed to 'alaw' [Apr 30 16:28:04] DEBUG[5292] chan_iax2.c: Sending 280 on 1236/16385 to 88.191.79.104:4569 [Apr 30 16:28:04] VERBOSE[5292] chan_iax2.c: Tx-Frame Retry[-01] -- OSeqno: 003 ISeqno: 004 Type: IAX Subclass: ACK [Apr 30 16:28:04] VERBOSE[5292] chan_iax2.c: Timestamp: 00280ms SCall: 01236 DCall: 16385 [88.191.79.104:4569] [Apr 30 16:28:04] DEBUG[5292] chan_iax2.c: For call=1236, set last=280 [Apr 30 16:28:04] DEBUG[5293] chan_iax2.c: Created trunk peer for '88.191.79.104:4569' [Apr 30 16:28:04] DEBUG[5317] pbx.c: Launching 'MusicOnHold' [Apr 30 16:28:04] VERBOSE[5317] pbx.c: -- Executing [3102@dediax:2] MusicOnHold("IAX2/dediax-1236", "") in new stack [Apr 30 16:28:04] VERBOSE[5317] res_musiconhold.c: -- Started music on hold, class 'default', on IAX2/dediax-1236 [Apr 30 16:28:04] DEBUG[5317] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Apr 30 16:28:04] DEBUG[5317] channel.c: Set channel IAX2/dediax-1236 to write format slin [Apr 30 16:28:04] DEBUG[5317] res_musiconhold.c: IAX2/dediax-1236 Opened file 0 '/var/lib/asterisk/moh/manolo_camp-morning_coffee' [Apr 30 16:28:04] DEBUG[5317] chan_iax2.c: predicted timestamp skew (312) > max (160), using real ts instead. [Apr 30 16:28:04] DEBUG[5290] chan_iax2.c: Sending 320 on 1236/16385 to 88.191.79.104:4569 [Apr 30 16:28:04] VERBOSE[5290] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 003 ISeqno: 004 Type: VOICE Subclass: 8 [Apr 30 16:28:04] VERBOSE[5290] chan_iax2.c: Timestamp: 00320ms SCall: 01236 DCall: 16385 [88.191.79.104:4569] [Apr 30 16:28:04] VERBOSE[5299] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 004 Type: IAX Subclass: ACK [Apr 30 16:28:04] VERBOSE[5299] chan_iax2.c: Timestamp: 00320ms SCall: 16385 DCall: 01236 [88.191.79.104:4569] [Apr 30 16:28:04] DEBUG[5299] chan_iax2.c: Received packet 4, (6, 4) [Apr 30 16:28:04] DEBUG[5299] chan_iax2.c: Cancelling transmission of packet 3 [Apr 30 16:28:04] DEBUG[5299] chan_iax2.c: IAX subclass 4 received [Apr 30 16:28:04] DEBUG[5317] chan_iax2.c: Expanded trunk '88.191.79.104:4569' to 6400 bytes [Apr 30 16:28:13] VERBOSE[5299] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 004 Type: IAX Subclass: LAGRQ [Apr 30 16:28:13] VERBOSE[5299] chan_iax2.c: Timestamp: 10032ms SCall: 16385 DCall: 01236 [88.191.79.104:4569] [Apr 30 16:28:13] DEBUG[5299] chan_iax2.c: Received packet 4, (6, 11) [Apr 30 16:28:13] DEBUG[5299] chan_iax2.c: IAX subclass 11 received [Apr 30 16:28:13] DEBUG[5299] chan_iax2.c: For call=1236, set last=10032 [Apr 30 16:28:13] DEBUG[5290] chan_iax2.c: Sending 10032 on 1236/16385 to 88.191.79.104:4569 [Apr 30 16:28:13] VERBOSE[5290] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 004 ISeqno: 005 Type: IAX Subclass: LAGRP [Apr 30 16:28:13] VERBOSE[5290] chan_iax2.c: Timestamp: 10032ms SCall: 01236 DCall: 16385 [88.191.79.104:4569] [Apr 30 16:28:13] VERBOSE[5301] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 005 ISeqno: 005 Type: IAX Subclass: ACK [Apr 30 16:28:13] VERBOSE[5301] chan_iax2.c: Timestamp: 10032ms SCall: 16385 DCall: 01236 [88.191.79.104:4569] [Apr 30 16:28:13] DEBUG[5301] chan_iax2.c: Received packet 5, (6, 4) [Apr 30 16:28:13] DEBUG[5301] chan_iax2.c: Cancelling transmission of packet 4 [Apr 30 16:28:13] DEBUG[5301] chan_iax2.c: IAX subclass 4 received [Apr 30 16:28:13] DEBUG[5290] chan_iax2.c: Sending 10021 on 1236/16385 to 88.191.79.104:4569 [Apr 30 16:28:13] VERBOSE[5290] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 005 ISeqno: 005 Type: IAX Subclass: LAGRQ [Apr 30 16:28:13] VERBOSE[5290] chan_iax2.c: Timestamp: 10021ms SCall: 01236 DCall: 16385 [88.191.79.104:4569] [Apr 30 16:28:13] VERBOSE[5300] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 005 ISeqno: 006 Type: IAX Subclass: LAGRP [Apr 30 16:28:13] VERBOSE[5300] chan_iax2.c: Timestamp: 10021ms SCall: 16385 DCall: 01236 [88.191.79.104:4569] [Apr 30 16:28:13] DEBUG[5300] chan_iax2.c: Received packet 5, (6, 12) [Apr 30 16:28:13] DEBUG[5300] chan_iax2.c: Cancelling transmission of packet 5 [Apr 30 16:28:13] DEBUG[5300] chan_iax2.c: IAX subclass 12 received [Apr 30 16:28:13] DEBUG[5300] chan_iax2.c: Peer 88.191.79.104 lag measured as 20ms [Apr 30 16:28:13] DEBUG[5300] chan_iax2.c: Sending 10021 on 1236/16385 to 88.191.79.104:4569 [Apr 30 16:28:13] VERBOSE[5300] chan_iax2.c: Tx-Frame Retry[-01] -- OSeqno: 006 ISeqno: 006 Type: IAX Subclass: ACK [Apr 30 16:28:13] VERBOSE[5300] chan_iax2.c: Timestamp: 10021ms SCall: 01236 DCall: 16385 [88.191.79.104:4569] [Apr 30 16:28:23] DEBUG[5290] chan_iax2.c: Sending 20021 on 1236/16385 to 88.191.79.104:4569 [Apr 30 16:28:23] VERBOSE[5290] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 006 ISeqno: 006 Type: IAX Subclass: LAGRQ [Apr 30 16:28:23] VERBOSE[5290] chan_iax2.c: Timestamp: 20021ms SCall: 01236 DCall: 16385 [88.191.79.104:4569] [Apr 30 16:28:23] VERBOSE[5295] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: INVAL [Apr 30 16:28:23] VERBOSE[5295] chan_iax2.c: Timestamp: 00000ms SCall: 16385 DCall: 01236 [88.191.79.104:4569] [Apr 30 16:28:23] DEBUG[5295] chan_iax2.c: Received packet 0, (6, 10) [Apr 30 16:28:23] DEBUG[5295] chan_iax2.c: IAX subclass 10 received [Apr 30 16:28:23] DEBUG[5295] chan_iax2.c: Immediately destroying 1236, having received INVAL [Apr 30 16:28:23] DEBUG[5295] chan_iax2.c: Destroying call 1236 [Apr 30 16:28:23] VERBOSE[5317] res_musiconhold.c: -- Stopped music on hold on IAX2/dediax-1236 [Apr 30 16:28:23] DEBUG[5317] channel.c: Set channel IAX2/dediax-1236 to write format alaw [Apr 30 16:28:23] DEBUG[5317] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Apr 30 16:28:23] DEBUG[5317] pbx.c: Spawn extension (dediax,3102,2) exited non-zero on 'IAX2/dediax-1236' [Apr 30 16:28:23] VERBOSE[5317] pbx.c: == Spawn extension (dediax, 3102, 2) exited non-zero on 'IAX2/dediax-1236' [Apr 30 16:28:23] DEBUG[5317] channel.c: Soft-Hanging up channel 'IAX2/dediax-1236' [Apr 30 16:28:23] DEBUG[5317] channel.c: Hanging up channel 'IAX2/dediax-1236' [Apr 30 16:28:23] DEBUG[5317] chan_iax2.c: We're hanging up IAX2/dediax-1236 now... [Apr 30 16:28:23] VERBOSE[5317] chan_iax2.c: -- Hungup 'IAX2/dediax-1236' [Apr 30 16:28:23] DEBUG[5277] devicestate.c: No provider found, checking channel drivers for IAX2 - dediax [Apr 30 16:28:23] DEBUG[5277] chan_iax2.c: Checking device state for device dediax [Apr 30 16:28:23] DEBUG[5277] chan_iax2.c: iax2_devicestate: Found peer. What's device state of dediax? addr=1488932712, defaddr=0 maxms=2000, lastms=40 [Apr 30 16:28:23] DEBUG[5277] devicestate.c: Changing state for IAX2/dediax - state 0 (Unknown) [Apr 30 16:28:23] DEBUG[5277] devicestate.c: device 'IAX2/dediax' state '0' [Apr 30 16:28:23] DEBUG[5313] app_queue.c: Device 'IAX2/dediax' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Apr 30 16:28:23] VERBOSE[5292] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE [Apr 30 16:28:23] VERBOSE[5292] chan_iax2.c: Timestamp: 00012ms SCall: 15307 DCall: 00000 [88.191.79.104:4569] [Apr 30 16:28:23] VERBOSE[5292] chan_iax2.c: Tx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG [Apr 30 16:28:23] VERBOSE[5292] chan_iax2.c: Timestamp: 00012ms SCall: 00001 DCall: 15307 [88.191.79.104:4569] [Apr 30 16:28:23] VERBOSE[5297] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK [Apr 30 16:28:23] VERBOSE[5297] chan_iax2.c: Timestamp: 00012ms SCall: 15307 DCall: 00001 [88.191.79.104:4569] [Apr 30 16:28:29] DEBUG[5302] chan_iax2.c: Dropping unused iax2 trunk peer '88.191.79.104:4569' [Apr 30 16:28:32] VERBOSE[5298] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: NEW [Apr 30 16:28:32] VERBOSE[5298] chan_iax2.c: Timestamp: 00016ms SCall: 16384 DCall: 00000 [88.191.79.104:4569] [Apr 30 16:28:32] VERBOSE[5298] chan_iax2.c: VERSION : 2 [Apr 30 16:28:32] VERBOSE[5298] chan_iax2.c: CALLED NUMBER : 3102 [Apr 30 16:28:32] VERBOSE[5298] chan_iax2.c: CODEC_PREFS : (alaw) [Apr 30 16:28:32] VERBOSE[5298] chan_iax2.c: CALLING NUMBER : 2075 [Apr 30 16:28:32] VERBOSE[5298] chan_iax2.c: CALLING PRESNTN : 0 [Apr 30 16:28:32] VERBOSE[5298] chan_iax2.c: CALLING TYPEOFN : 0 [Apr 30 16:28:32] VERBOSE[5298] chan_iax2.c: CALLING TRANSIT : 0 [Apr 30 16:28:32] VERBOSE[5298] chan_iax2.c: CALLING NAME : Julien Lafont [Apr 30 16:28:32] VERBOSE[5298] chan_iax2.c: LANGUAGE : en [Apr 30 16:28:32] VERBOSE[5298] chan_iax2.c: USERNAME : dediax [Apr 30 16:28:32] VERBOSE[5298] chan_iax2.c: FORMAT : 8 [Apr 30 16:28:32] VERBOSE[5298] chan_iax2.c: CAPABILITY : 1105928 [Apr 30 16:28:32] VERBOSE[5298] chan_iax2.c: ADSICPE : 2 [Apr 30 16:28:32] VERBOSE[5298] chan_iax2.c: DATE TIME : 2012-04-30 16:28:32 [Apr 30 16:28:32] VERBOSE[5298] chan_iax2.c: [Apr 30 16:28:32] DEBUG[5298] chan_iax2.c: Determining if address 88.191.79.104 with username dediax requires calltoken validation. Optional = 1 calltoken_required = 0 [Apr 30 16:28:32] DEBUG[5298] chan_iax2.c: ip callno count incremented to 3 for 88.191.79.104 [Apr 30 16:28:32] DEBUG[5298] chan_iax2.c: Creating new call structure 1528 [Apr 30 16:28:32] DEBUG[5298] chan_iax2.c: Received packet 0, (6, 1) [Apr 30 16:28:32] DEBUG[5298] chan_iax2.c: IAX subclass 1 received [Apr 30 16:28:32] DEBUG[5298] chan_iax2.c: For call=1528, set last=16 [Apr 30 16:28:32] VERBOSE[5298] chan_iax2.c: -- Accepting UNAUTHENTICATED call from 88.191.79.104: > requested format = alaw, > requested prefs = (alaw), > actual format = alaw, > host prefs = (g729|alaw), > priority = mine [Apr 30 16:28:32] DEBUG[5290] chan_iax2.c: Sending 5 on 1528/16384 to 88.191.79.104:4569 [Apr 30 16:28:32] VERBOSE[5290] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: ACCEPT [Apr 30 16:28:32] VERBOSE[5290] chan_iax2.c: Timestamp: 00005ms SCall: 01528 DCall: 16384 [88.191.79.104:4569] [Apr 30 16:28:32] VERBOSE[5290] chan_iax2.c: FORMAT : 8 [Apr 30 16:28:32] VERBOSE[5290] chan_iax2.c: FORMAT2 : alaw [Apr 30 16:28:32] VERBOSE[5290] chan_iax2.c: [Apr 30 16:28:32] VERBOSE[5296] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK [Apr 30 16:28:32] VERBOSE[5296] chan_iax2.c: Timestamp: 00005ms SCall: 16384 DCall: 01528 [88.191.79.104:4569] [Apr 30 16:28:32] DEBUG[5296] chan_iax2.c: Received packet 1, (6, 4) [Apr 30 16:28:32] DEBUG[5296] chan_iax2.c: Cancelling transmission of packet 0 [Apr 30 16:28:32] DEBUG[5296] chan_iax2.c: IAX subclass 4 received [Apr 30 16:28:32] DEBUG[5318] pbx.c: Launching 'Answer' [Apr 30 16:28:32] VERBOSE[5318] pbx.c: -- Executing [3102@dediax:1] Answer("IAX2/dediax-1528", "") in new stack [Apr 30 16:28:32] DEBUG[5318] chan_iax2.c: Answering IAX2 call [Apr 30 16:28:32] DEBUG[5318] chan_iax2.c: Indicating condition -1 [Apr 30 16:28:32] DEBUG[5277] devicestate.c: No provider found, checking channel drivers for IAX2 - dediax [Apr 30 16:28:32] DEBUG[5277] chan_iax2.c: Checking device state for device dediax [Apr 30 16:28:32] DEBUG[5277] chan_iax2.c: iax2_devicestate: Found peer. What's device state of dediax? addr=1488932712, defaddr=0 maxms=2000, lastms=40 [Apr 30 16:28:32] DEBUG[5277] devicestate.c: Changing state for IAX2/dediax - state 2 (In use) [Apr 30 16:28:32] DEBUG[5277] devicestate.c: device 'IAX2/dediax' state '2' [Apr 30 16:28:32] DEBUG[5290] chan_iax2.c: Sending 8 on 1528/16384 to 88.191.79.104:4569 [Apr 30 16:28:32] VERBOSE[5290] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 001 Type: CONTROL Subclass: ANSWER [Apr 30 16:28:32] VERBOSE[5290] chan_iax2.c: Timestamp: 00008ms SCall: 01528 DCall: 16384 [88.191.79.104:4569] [Apr 30 16:28:32] DEBUG[5313] app_queue.c: Device 'IAX2/dediax' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Apr 30 16:28:32] DEBUG[5290] chan_iax2.c: Sending 11 on 1528/16384 to 88.191.79.104:4569 [Apr 30 16:28:32] VERBOSE[5290] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 002 ISeqno: 001 Type: CONTROL Subclass: (255?) [Apr 30 16:28:32] VERBOSE[5290] chan_iax2.c: Timestamp: 00011ms SCall: 01528 DCall: 16384 [88.191.79.104:4569] [Apr 30 16:28:32] VERBOSE[5300] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: ACK [Apr 30 16:28:32] VERBOSE[5300] chan_iax2.c: Timestamp: 00008ms SCall: 16384 DCall: 01528 [88.191.79.104:4569] [Apr 30 16:28:32] DEBUG[5300] chan_iax2.c: Received packet 1, (6, 4) [Apr 30 16:28:32] DEBUG[5300] chan_iax2.c: Cancelling transmission of packet 1 [Apr 30 16:28:32] DEBUG[5300] chan_iax2.c: IAX subclass 4 received [Apr 30 16:28:32] VERBOSE[5300] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 003 Type: IAX Subclass: ACK [Apr 30 16:28:32] VERBOSE[5300] chan_iax2.c: Timestamp: 00011ms SCall: 16384 DCall: 01528 [88.191.79.104:4569] [Apr 30 16:28:32] DEBUG[5300] chan_iax2.c: Received packet 1, (6, 4) [Apr 30 16:28:32] DEBUG[5300] chan_iax2.c: Cancelling transmission of packet 2 [Apr 30 16:28:32] DEBUG[5300] chan_iax2.c: IAX subclass 4 received [Apr 30 16:28:32] VERBOSE[5294] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 003 Type: CONTROL Subclass: SRCUPDT [Apr 30 16:28:32] VERBOSE[5294] chan_iax2.c: Timestamp: 00019ms SCall: 16384 DCall: 01528 [88.191.79.104:4569] [Apr 30 16:28:32] DEBUG[5294] chan_iax2.c: Received packet 1, (4, 20) [Apr 30 16:28:32] DEBUG[5294] chan_iax2.c: Sending 19 on 1528/16384 to 88.191.79.104:4569 [Apr 30 16:28:32] VERBOSE[5294] chan_iax2.c: Tx-Frame Retry[-01] -- OSeqno: 003 ISeqno: 002 Type: IAX Subclass: ACK [Apr 30 16:28:32] VERBOSE[5294] chan_iax2.c: Timestamp: 00019ms SCall: 01528 DCall: 16384 [88.191.79.104:4569] [Apr 30 16:28:32] DEBUG[5294] chan_iax2.c: calc_rxstamp: call=1528: rxcore set to 1335796112.215872 - 19ms [Apr 30 16:28:32] DEBUG[5294] chan_iax2.c: calc_rxstamp: call=1528: works out as 1335796112.196872 [Apr 30 16:28:32] DEBUG[5294] chan_iax2.c: For call=1528, set last=19 [Apr 30 16:28:32] VERBOSE[5301] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 003 Type: CONTROL Subclass: SRCUPDT [Apr 30 16:28:32] VERBOSE[5301] chan_iax2.c: Timestamp: 00022ms SCall: 16384 DCall: 01528 [88.191.79.104:4569] [Apr 30 16:28:32] DEBUG[5301] chan_iax2.c: Received packet 2, (4, 20) [Apr 30 16:28:32] DEBUG[5301] chan_iax2.c: Sending 22 on 1528/16384 to 88.191.79.104:4569 [Apr 30 16:28:32] VERBOSE[5301] chan_iax2.c: Tx-Frame Retry[-01] -- OSeqno: 003 ISeqno: 003 Type: IAX Subclass: ACK [Apr 30 16:28:32] VERBOSE[5301] chan_iax2.c: Timestamp: 00022ms SCall: 01528 DCall: 16384 [88.191.79.104:4569] [Apr 30 16:28:32] DEBUG[5301] chan_iax2.c: For call=1528, set last=22 [Apr 30 16:28:32] VERBOSE[5297] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 003 ISeqno: 003 Type: VOICE Subclass: 8 [Apr 30 16:28:32] VERBOSE[5297] chan_iax2.c: Timestamp: 00240ms SCall: 16384 DCall: 01528 [88.191.79.104:4569] [Apr 30 16:28:32] DEBUG[5297] chan_iax2.c: Received packet 3, (2, 8) [Apr 30 16:28:32] DEBUG[5297] chan_iax2.c: Ooh, voice format changed to 'alaw' [Apr 30 16:28:32] DEBUG[5297] chan_iax2.c: Sending 240 on 1528/16384 to 88.191.79.104:4569 [Apr 30 16:28:32] VERBOSE[5297] chan_iax2.c: Tx-Frame Retry[-01] -- OSeqno: 003 ISeqno: 004 Type: IAX Subclass: ACK [Apr 30 16:28:32] VERBOSE[5297] chan_iax2.c: Timestamp: 00240ms SCall: 01528 DCall: 16384 [88.191.79.104:4569] [Apr 30 16:28:32] DEBUG[5297] chan_iax2.c: For call=1528, set last=240 [Apr 30 16:28:32] DEBUG[5293] chan_iax2.c: Created trunk peer for '88.191.79.104:4569' [Apr 30 16:28:32] DEBUG[5318] pbx.c: Launching 'MusicOnHold' [Apr 30 16:28:32] VERBOSE[5318] pbx.c: -- Executing [3102@dediax:2] MusicOnHold("IAX2/dediax-1528", "") in new stack [Apr 30 16:28:32] VERBOSE[5318] res_musiconhold.c: -- Started music on hold, class 'default', on IAX2/dediax-1528 [Apr 30 16:28:32] DEBUG[5318] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Apr 30 16:28:32] DEBUG[5318] channel.c: Set channel IAX2/dediax-1528 to write format slin [Apr 30 16:28:32] DEBUG[5318] res_musiconhold.c: IAX2/dediax-1528 Opened file 0 '/var/lib/asterisk/moh/manolo_camp-morning_coffee' [Apr 30 16:28:32] DEBUG[5318] chan_iax2.c: predicted timestamp skew (312) > max (160), using real ts instead. [Apr 30 16:28:32] DEBUG[5290] chan_iax2.c: Sending 320 on 1528/16384 to 88.191.79.104:4569 [Apr 30 16:28:32] VERBOSE[5290] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 003 ISeqno: 004 Type: VOICE Subclass: 8 [Apr 30 16:28:32] VERBOSE[5290] chan_iax2.c: Timestamp: 00320ms SCall: 01528 DCall: 16384 [88.191.79.104:4569] [Apr 30 16:28:32] DEBUG[5318] chan_iax2.c: Expanded trunk '88.191.79.104:4569' to 6400 bytes [Apr 30 16:28:32] VERBOSE[5292] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 004 Type: IAX Subclass: ACK [Apr 30 16:28:32] VERBOSE[5292] chan_iax2.c: Timestamp: 00320ms SCall: 16384 DCall: 01528 [88.191.79.104:4569] [Apr 30 16:28:32] DEBUG[5292] chan_iax2.c: Received packet 4, (6, 4) [Apr 30 16:28:32] DEBUG[5292] chan_iax2.c: Cancelling transmission of packet 3 [Apr 30 16:28:32] DEBUG[5292] chan_iax2.c: IAX subclass 4 received [Apr 30 16:28:33] DEBUG[5291] chan_iax2.c: Really destroying 1236 now... [Apr 30 16:28:33] DEBUG[5291] chan_iax2.c: schedule decrement of callno used for 88.191.79.104 in 60 seconds [Apr 30 16:28:39] DEBUG[5318] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [Apr 30 16:28:42] DEBUG[5290] chan_iax2.c: Sending 9993 on 1528/16384 to 88.191.79.104:4569 [Apr 30 16:28:42] VERBOSE[5290] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 004 ISeqno: 004 Type: IAX Subclass: LAGRQ [Apr 30 16:28:42] VERBOSE[5290] chan_iax2.c: Timestamp: 09993ms SCall: 01528 DCall: 16384 [88.191.79.104:4569] [Apr 30 16:28:42] VERBOSE[5301] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 004 ISeqno: 004 Type: IAX Subclass: LAGRQ [Apr 30 16:28:42] VERBOSE[5301] chan_iax2.c: Timestamp: 10031ms SCall: 16384 DCall: 01528 [88.191.79.104:4569] [Apr 30 16:28:42] DEBUG[5301] chan_iax2.c: Received packet 4, (6, 11) [Apr 30 16:28:42] DEBUG[5301] chan_iax2.c: IAX subclass 11 received [Apr 30 16:28:42] DEBUG[5301] chan_iax2.c: For call=1528, set last=10031 [Apr 30 16:28:42] DEBUG[5290] chan_iax2.c: Sending 10031 on 1528/16384 to 88.191.79.104:4569 [Apr 30 16:28:42] VERBOSE[5290] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 005 ISeqno: 005 Type: IAX Subclass: LAGRP [Apr 30 16:28:42] VERBOSE[5290] chan_iax2.c: Timestamp: 10031ms SCall: 01528 DCall: 16384 [88.191.79.104:4569] [Apr 30 16:28:42] VERBOSE[5297] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 005 ISeqno: 005 Type: IAX Subclass: LAGRP [Apr 30 16:28:42] VERBOSE[5297] chan_iax2.c: Timestamp: 09993ms SCall: 16384 DCall: 01528 [88.191.79.104:4569] [Apr 30 16:28:42] DEBUG[5297] chan_iax2.c: Received packet 5, (6, 12) [Apr 30 16:28:42] DEBUG[5297] chan_iax2.c: Cancelling transmission of packet 4 [Apr 30 16:28:42] DEBUG[5297] chan_iax2.c: IAX subclass 12 received [Apr 30 16:28:42] DEBUG[5297] chan_iax2.c: Peer 88.191.79.104 lag measured as 219ms [Apr 30 16:28:42] DEBUG[5297] chan_iax2.c: Sending 9993 on 1528/16384 to 88.191.79.104:4569 [Apr 30 16:28:42] VERBOSE[5297] chan_iax2.c: Tx-Frame Retry[-01] -- OSeqno: 005 ISeqno: 006 Type: IAX Subclass: ACK [Apr 30 16:28:42] VERBOSE[5297] chan_iax2.c: Timestamp: 09993ms SCall: 01528 DCall: 16384 [88.191.79.104:4569] [Apr 30 16:28:42] VERBOSE[5299] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 005 ISeqno: 006 Type: IAX Subclass: ACK [Apr 30 16:28:42] VERBOSE[5299] chan_iax2.c: Timestamp: 10031ms SCall: 16384 DCall: 01528 [88.191.79.104:4569] [Apr 30 16:28:42] DEBUG[5299] chan_iax2.c: Received packet 5, (6, 4) [Apr 30 16:28:42] DEBUG[5299] chan_iax2.c: Cancelling transmission of packet 5 [Apr 30 16:28:42] DEBUG[5299] chan_iax2.c: IAX subclass 4 received [Apr 30 16:28:42] DEBUG[5318] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [Apr 30 16:28:45] DEBUG[5291] chan_iax2.c: ip callno count decremented to 2 for 88.191.79.104 [Apr 30 16:28:45] DEBUG[5299] chan_iax2.c: ip callno count incremented to 3 for 88.191.79.104 [Apr 30 16:28:45] DEBUG[5299] chan_iax2.c: Creating new call structure 3855 [Apr 30 16:28:45] DEBUG[5290] chan_iax2.c: Sending 19 on 3855/0 to 88.191.79.104:4569 [Apr 30 16:28:45] VERBOSE[5290] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE [Apr 30 16:28:45] VERBOSE[5290] chan_iax2.c: Timestamp: 00019ms SCall: 03855 DCall: 00000 [88.191.79.104:4569] [Apr 30 16:28:45] VERBOSE[5290] chan_iax2.c: [Apr 30 16:28:46] VERBOSE[5295] chan_iax2.c: Rx-Frame Retry[Yes] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: PONG [Apr 30 16:28:46] VERBOSE[5295] chan_iax2.c: Timestamp: 00000ms SCall: 00001 DCall: 03855 [88.191.79.104:4569] [Apr 30 16:28:46] DEBUG[5295] chan_iax2.c: Received packet 0, (6, 3) [Apr 30 16:28:46] DEBUG[5295] chan_iax2.c: IAX subclass 3 received [Apr 30 16:28:46] DEBUG[5295] chan_iax2.c: Sending 272 on 3855/1 to 88.191.79.104:4569 [Apr 30 16:28:46] VERBOSE[5295] chan_iax2.c: Tx-Frame Retry[-01] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: ACK [Apr 30 16:28:46] VERBOSE[5295] chan_iax2.c: Timestamp: 00272ms SCall: 03855 DCall: 00001 [88.191.79.104:4569] [Apr 30 16:28:46] DEBUG[5295] chan_iax2.c: schedule decrement of callno used for 88.191.79.104 in 60 seconds [Apr 30 16:28:46] DEBUG[5295] chan_iax2.c: Peer dediax: got pong, lastms 269, historicms 269, maxms 2000 [Apr 30 16:28:52] DEBUG[5290] chan_iax2.c: Sending 19973 on 1528/16384 to 88.191.79.104:4569 [Apr 30 16:28:52] VERBOSE[5290] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 006 ISeqno: 006 Type: IAX Subclass: LAGRQ [Apr 30 16:28:52] VERBOSE[5290] chan_iax2.c: Timestamp: 19973ms SCall: 01528 DCall: 16384 [88.191.79.104:4569] [Apr 30 16:28:52] VERBOSE[5292] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 006 ISeqno: 006 Type: IAX Subclass: LAGRQ [Apr 30 16:28:52] VERBOSE[5292] chan_iax2.c: Timestamp: 20030ms SCall: 16384 DCall: 01528 [88.191.79.104:4569] [Apr 30 16:28:52] DEBUG[5292] chan_iax2.c: Received packet 6, (6, 11) [Apr 30 16:28:52] DEBUG[5292] chan_iax2.c: IAX subclass 11 received [Apr 30 16:28:52] DEBUG[5292] chan_iax2.c: For call=1528, set last=20030 [Apr 30 16:28:52] DEBUG[5290] chan_iax2.c: Sending 20030 on 1528/16384 to 88.191.79.104:4569 [Apr 30 16:28:52] VERBOSE[5290] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 007 ISeqno: 007 Type: IAX Subclass: LAGRP [Apr 30 16:28:52] VERBOSE[5290] chan_iax2.c: Timestamp: 20030ms SCall: 01528 DCall: 16384 [88.191.79.104:4569] [Apr 30 16:28:52] VERBOSE[5293] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 007 ISeqno: 007 Type: IAX Subclass: LAGRP [Apr 30 16:28:52] VERBOSE[5293] chan_iax2.c: Timestamp: 19973ms SCall: 16384 DCall: 01528 [88.191.79.104:4569] [Apr 30 16:28:52] DEBUG[5293] chan_iax2.c: Received packet 7, (6, 12) [Apr 30 16:28:52] DEBUG[5293] chan_iax2.c: Cancelling transmission of packet 6 [Apr 30 16:28:52] DEBUG[5293] chan_iax2.c: IAX subclass 12 received [Apr 30 16:28:52] DEBUG[5293] chan_iax2.c: Peer 88.191.79.104 lag measured as 245ms [Apr 30 16:28:52] DEBUG[5293] chan_iax2.c: Sending 19973 on 1528/16384 to 88.191.79.104:4569 [Apr 30 16:28:52] VERBOSE[5293] chan_iax2.c: Tx-Frame Retry[-01] -- OSeqno: 007 ISeqno: 008 Type: IAX Subclass: ACK [Apr 30 16:28:52] VERBOSE[5293] chan_iax2.c: Timestamp: 19973ms SCall: 01528 DCall: 16384 [88.191.79.104:4569] [Apr 30 16:28:52] VERBOSE[5298] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 007 ISeqno: 008 Type: IAX Subclass: ACK [Apr 30 16:28:52] VERBOSE[5298] chan_iax2.c: Timestamp: 20030ms SCall: 16384 DCall: 01528 [88.191.79.104:4569] [Apr 30 16:28:52] DEBUG[5298] chan_iax2.c: Received packet 7, (6, 4) [Apr 30 16:28:52] DEBUG[5298] chan_iax2.c: Cancelling transmission of packet 7 [Apr 30 16:28:52] DEBUG[5298] chan_iax2.c: IAX subclass 4 received [Apr 30 16:28:53] DEBUG[5290] chan_iax2.c: Sending 20974 on 1528/16384 to 88.191.79.104:4569 [Apr 30 16:28:53] VERBOSE[5290] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 008 ISeqno: 008 Type: IAX Subclass: PING [Apr 30 16:28:53] VERBOSE[5290] chan_iax2.c: Timestamp: 20974ms SCall: 01528 DCall: 16384 [88.191.79.104:4569] [Apr 30 16:28:53] VERBOSE[5299] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 008 ISeqno: 008 Type: IAX Subclass: PING [Apr 30 16:28:53] VERBOSE[5299] chan_iax2.c: Timestamp: 21031ms SCall: 16384 DCall: 01528 [88.191.79.104:4569] [Apr 30 16:28:53] DEBUG[5299] chan_iax2.c: Received packet 8, (6, 2) [Apr 30 16:28:53] DEBUG[5299] chan_iax2.c: IAX subclass 2 received [Apr 30 16:28:53] DEBUG[5299] chan_iax2.c: For call=1528, set last=21031 [Apr 30 16:28:53] DEBUG[5290] chan_iax2.c: Sending 21031 on 1528/16384 to 88.191.79.104:4569 [Apr 30 16:28:53] VERBOSE[5290] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 009 ISeqno: 009 Type: IAX Subclass: PONG [Apr 30 16:28:53] VERBOSE[5290] chan_iax2.c: Timestamp: 21031ms SCall: 01528 DCall: 16384 [88.191.79.104:4569] [Apr 30 16:28:53] VERBOSE[5290] chan_iax2.c: RR_JITTER : 22 [Apr 30 16:28:53] VERBOSE[5290] chan_iax2.c: RR_LOSS : 1 [Apr 30 16:28:53] VERBOSE[5290] chan_iax2.c: RR_PKTS : 1040 [Apr 30 16:28:53] VERBOSE[5290] chan_iax2.c: RR_DELAY : 71 [Apr 30 16:28:53] VERBOSE[5290] chan_iax2.c: RR_DROPPED : 0 [Apr 30 16:28:53] VERBOSE[5290] chan_iax2.c: RR_OUTOFORDER : 11 [Apr 30 16:28:53] VERBOSE[5290] chan_iax2.c: [Apr 30 16:28:53] VERBOSE[5300] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 009 ISeqno: 009 Type: IAX Subclass: PONG [Apr 30 16:28:53] VERBOSE[5300] chan_iax2.c: Timestamp: 20974ms SCall: 16384 DCall: 01528 [88.191.79.104:4569] [Apr 30 16:28:53] VERBOSE[5300] chan_iax2.c: RR_JITTER : 0 [Apr 30 16:28:53] VERBOSE[5300] chan_iax2.c: RR_LOSS : 0 [Apr 30 16:28:53] VERBOSE[5300] chan_iax2.c: RR_PKTS : 1 [Apr 30 16:28:53] VERBOSE[5300] chan_iax2.c: RR_DELAY : 40 [Apr 30 16:28:53] VERBOSE[5300] chan_iax2.c: RR_DROPPED : 0 [Apr 30 16:28:53] VERBOSE[5300] chan_iax2.c: RR_OUTOFORDER : 0 [Apr 30 16:28:53] VERBOSE[5300] chan_iax2.c: [Apr 30 16:28:53] DEBUG[5300] chan_iax2.c: Received packet 9, (6, 3) [Apr 30 16:28:53] DEBUG[5300] chan_iax2.c: Cancelling transmission of packet 8 [Apr 30 16:28:53] DEBUG[5300] chan_iax2.c: IAX subclass 3 received [Apr 30 16:28:53] DEBUG[5300] chan_iax2.c: JB STATS:IAX2/dediax-1528 ping=239 ljitterms=22 ljbdelayms=71 ltotlost=1 lrecentlosspct=0 ldropped=0 looo=11 lrecvd=1041 rjitterms=0 rjbdelayms=40 rtotlost=0 rrecentlosspct=0 rdropped=0 rooo=0 rrecvd=1 [Apr 30 16:28:53] DEBUG[5300] chan_iax2.c: Sending 20974 on 1528/16384 to 88.191.79.104:4569 [Apr 30 16:28:53] VERBOSE[5300] chan_iax2.c: Tx-Frame Retry[-01] -- OSeqno: 009 ISeqno: 010 Type: IAX Subclass: ACK [Apr 30 16:28:53] VERBOSE[5300] chan_iax2.c: Timestamp: 20974ms SCall: 01528 DCall: 16384 [88.191.79.104:4569] [Apr 30 16:28:53] VERBOSE[5301] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 009 ISeqno: 010 Type: IAX Subclass: ACK [Apr 30 16:28:53] VERBOSE[5301] chan_iax2.c: Timestamp: 21031ms SCall: 16384 DCall: 01528 [88.191.79.104:4569] [Apr 30 16:28:53] DEBUG[5301] chan_iax2.c: Received packet 9, (6, 4) [Apr 30 16:28:53] DEBUG[5301] chan_iax2.c: Cancelling transmission of packet 9 [Apr 30 16:28:53] DEBUG[5301] chan_iax2.c: IAX subclass 4 received [Apr 30 16:29:02] DEBUG[5290] chan_iax2.c: Sending 29973 on 1528/16384 to 88.191.79.104:4569 [Apr 30 16:29:02] VERBOSE[5290] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 010 ISeqno: 010 Type: IAX Subclass: LAGRQ [Apr 30 16:29:02] VERBOSE[5290] chan_iax2.c: Timestamp: 29973ms SCall: 01528 DCall: 16384 [88.191.79.104:4569] [Apr 30 16:29:02] VERBOSE[5293] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 010 ISeqno: 010 Type: IAX Subclass: LAGRQ [Apr 30 16:29:02] VERBOSE[5293] chan_iax2.c: Timestamp: 30030ms SCall: 16384 DCall: 01528 [88.191.79.104:4569] [Apr 30 16:29:02] DEBUG[5293] chan_iax2.c: Received packet 10, (6, 11) [Apr 30 16:29:02] DEBUG[5293] chan_iax2.c: IAX subclass 11 received [Apr 30 16:29:02] DEBUG[5293] chan_iax2.c: For call=1528, set last=30030 [Apr 30 16:29:02] DEBUG[5290] chan_iax2.c: Sending 30030 on 1528/16384 to 88.191.79.104:4569 [Apr 30 16:29:02] VERBOSE[5290] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 011 ISeqno: 011 Type: IAX Subclass: LAGRP [Apr 30 16:29:02] VERBOSE[5290] chan_iax2.c: Timestamp: 30030ms SCall: 01528 DCall: 16384 [88.191.79.104:4569] [Apr 30 16:29:02] VERBOSE[5297] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 011 ISeqno: 011 Type: IAX Subclass: LAGRP [Apr 30 16:29:02] VERBOSE[5297] chan_iax2.c: Timestamp: 29973ms SCall: 16384 DCall: 01528 [88.191.79.104:4569] [Apr 30 16:29:02] DEBUG[5297] chan_iax2.c: Received packet 11, (6, 12) [Apr 30 16:29:02] DEBUG[5297] chan_iax2.c: Cancelling transmission of packet 10 [Apr 30 16:29:02] DEBUG[5297] chan_iax2.c: IAX subclass 12 received [Apr 30 16:29:02] DEBUG[5297] chan_iax2.c: Peer 88.191.79.104 lag measured as 19ms [Apr 30 16:29:02] DEBUG[5297] chan_iax2.c: Sending 29973 on 1528/16384 to 88.191.79.104:4569 [Apr 30 16:29:02] VERBOSE[5297] chan_iax2.c: Tx-Frame Retry[-01] -- OSeqno: 011 ISeqno: 012 Type: IAX Subclass: ACK [Apr 30 16:29:02] VERBOSE[5297] chan_iax2.c: Timestamp: 29973ms SCall: 01528 DCall: 16384 [88.191.79.104:4569] [Apr 30 16:29:02] VERBOSE[5297] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 011 ISeqno: 012 Type: IAX Subclass: ACK [Apr 30 16:29:02] VERBOSE[5297] chan_iax2.c: Timestamp: 30030ms SCall: 16384 DCall: 01528 [88.191.79.104:4569] [Apr 30 16:29:02] DEBUG[5297] chan_iax2.c: Received packet 11, (6, 4) [Apr 30 16:29:02] DEBUG[5297] chan_iax2.c: Cancelling transmission of packet 11 [Apr 30 16:29:02] DEBUG[5297] chan_iax2.c: IAX subclass 4 received [Apr 30 16:29:11] DEBUG[5302] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [Apr 30 16:29:12] DEBUG[5290] chan_iax2.c: Sending 39972 on 1528/16384 to 88.191.79.104:4569 [Apr 30 16:29:12] VERBOSE[5290] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 012 ISeqno: 012 Type: IAX Subclass: LAGRQ [Apr 30 16:29:12] VERBOSE[5290] chan_iax2.c: Timestamp: 39972ms SCall: 01528 DCall: 16384 [88.191.79.104:4569] [Apr 30 16:29:12] VERBOSE[5300] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: INVAL [Apr 30 16:29:12] VERBOSE[5300] chan_iax2.c: Timestamp: 00000ms SCall: 16384 DCall: 01528 [88.191.79.104:4569] [Apr 30 16:29:12] DEBUG[5300] chan_iax2.c: Received packet 0, (6, 10) [Apr 30 16:29:12] DEBUG[5300] chan_iax2.c: IAX subclass 10 received [Apr 30 16:29:12] DEBUG[5300] chan_iax2.c: Immediately destroying 1528, having received INVAL [Apr 30 16:29:12] DEBUG[5300] chan_iax2.c: Destroying call 1528 [Apr 30 16:29:12] VERBOSE[5318] res_musiconhold.c: -- Stopped music on hold on IAX2/dediax-1528 [Apr 30 16:29:12] DEBUG[5318] channel.c: Set channel IAX2/dediax-1528 to write format alaw [Apr 30 16:29:12] DEBUG[5318] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Apr 30 16:29:18] DEBUG[5302] chan_iax2.c: Dropping unused iax2 trunk peer '88.191.79.104:4569' [Apr 30 16:29:22] DEBUG[5302] res_timing_timerfd.c: Expected to acknowledge 1 ticks but got 2 instead [Apr 30 16:29:24] VERBOSE[5296] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE [Apr 30 16:29:24] VERBOSE[5296] chan_iax2.c: Timestamp: 00003ms SCall: 13920 DCall: 00000 [88.191.79.104:4569] [Apr 30 16:29:24] VERBOSE[5296] chan_iax2.c: Tx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: PONG [Apr 30 16:29:24] VERBOSE[5296] chan_iax2.c: Timestamp: 00003ms SCall: 00001 DCall: 13920 [88.191.79.104:4569] [Apr 30 16:29:24] VERBOSE[5292] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: ACK [Apr 30 16:29:24] VERBOSE[5292] chan_iax2.c: Timestamp: 00003ms SCall: 13920 DCall: 00001 [88.191.79.104:4569] [Apr 30 16:29:33] DEBUG[5291] chan_iax2.c: ip callno count decremented to 2 for 88.191.79.104 [Apr 30 16:29:37] WARNING[5293] chan_iax2.c: Max retries exceeded to host 88.191.79.104 on IAX2/dediax-1528 (type = 6, subclass = 11, ts=39972, seqno=12) [Apr 30 16:29:39] WARNING[5300] chan_iax2.c: Max retries exceeded to host 88.191.79.104 on IAX2/dediax-1528 (type = 6, subclass = 2, ts=41973, seqno=13) [Apr 30 16:29:39] VERBOSE[5316] asterisk.c: -- Remote UNIX connection disconnected [Apr 30 16:29:46] DEBUG[5291] chan_iax2.c: ip callno count decremented to 1 for 88.191.79.104 [Apr 30 16:29:46] DEBUG[5297] chan_iax2.c: ip callno count incremented to 2 for 88.191.79.104 [Apr 30 16:29:46] DEBUG[5297] chan_iax2.c: Creating new call structure 2853 [Apr 30 16:29:46] DEBUG[5290] chan_iax2.c: Sending 8 on 2853/0 to 88.191.79.104:4569 [Apr 30 16:29:46] VERBOSE[5290] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: POKE [Apr 30 16:29:46] VERBOSE[5290] chan_iax2.c: Timestamp: 00008ms SCall: 02853 DCall: 00000 [88.191.79.104:4569] [Apr 30 16:29:46] VERBOSE[5290] chan_iax2.c: [Apr 30 16:29:46] VERBOSE[5301] chan_iax2.c: Rx-Frame Retry[Yes] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: PONG [Apr 30 16:29:46] VERBOSE[5301] chan_iax2.c: Timestamp: 00000ms SCall: 00001 DCall: 02853 [88.191.79.104:4569] [Apr 30 16:29:46] DEBUG[5301] chan_iax2.c: Received packet 0, (6, 3) [Apr 30 16:29:46] DEBUG[5301] chan_iax2.c: IAX subclass 3 received [Apr 30 16:29:46] DEBUG[5301] chan_iax2.c: Sending 31 on 2853/1 to 88.191.79.104:4569 [Apr 30 16:29:46] VERBOSE[5301] chan_iax2.c: Tx-Frame Retry[-01] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: ACK [Apr 30 16:29:46] VERBOSE[5301] chan_iax2.c: Timestamp: 00031ms SCall: 02853 DCall: 00001 [88.191.79.104:4569] [Apr 30 16:29:46] DEBUG[5301] chan_iax2.c: schedule decrement of callno used for 88.191.79.104 in 60 seconds [Apr 30 16:29:46] DEBUG[5301] chan_iax2.c: Peer dediax: got pong, lastms 28, historicms 28, maxms 2000 [Apr 30 16:29:47] WARNING[5292] chan_iax2.c: Max retries exceeded to host 88.191.79.104 on IAX2/dediax-1528 (type = 6, subclass = 11, ts=49972, seqno=14) [Apr 30 16:29:57] WARNING[5295] chan_iax2.c: Max retries exceeded to host 88.191.79.104 on IAX2/dediax-1528 (type = 6, subclass = 11, ts=59972, seqno=15) [Apr 30 16:30:00] WARNING[5293] chan_iax2.c: Max retries exceeded to host 88.191.79.104 on IAX2/dediax-1528 (type = 6, subclass = 2, ts=62973, seqno=16) [Apr 30 16:30:07] WARNING[5298] chan_iax2.c: Max retries exceeded to host 88.191.79.104 on IAX2/dediax-1528 (type = 6, subclass = 11, ts=69971, seqno=17)