[Jun 12 17:37:22] VERBOSE[4768] config.c: == Parsing '/etc/asterisk/logger.conf': [Jun 12 17:37:22] DEBUG[4768] config.c: Parsing /etc/asterisk/logger.conf [Jun 12 17:37:22] VERBOSE[4768] config.c: == Found [Jun 12 17:37:22] VERBOSE[4768] logger.c: Asterisk Queue Logger restarted [Jun 12 17:37:22] DEBUG[2934] chan_iax2.c: ip callno count incremented to 2 for 10.28.130.121 [Jun 12 17:37:22] DEBUG[2919] devicestate.c: No provider found, checking channel drivers for IAX2 - em_2 [Jun 12 17:37:22] DEBUG[2919] chan_iax2.c: Checking device state for device em_2 [Jun 12 17:37:22] DEBUG[2919] chan_iax2.c: iax2_devicestate: Found peer. What's device state of em_2? addr=169640569, defaddr=0 maxms=0, lastms=0 [Jun 12 17:37:22] DEBUG[2919] devicestate.c: Changing state for IAX2/em_2 - state 0 (Unknown) [Jun 12 17:37:22] DEBUG[2919] devicestate.c: device 'IAX2/em_2' state '0' [Jun 12 17:37:22] DEBUG[2954] app_queue.c: Device 'IAX2/em_2' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 12 17:37:22] DEBUG[2919] devicestate.c: No provider found, checking channel drivers for IAX2 - em_2 [Jun 12 17:37:22] DEBUG[2919] chan_iax2.c: Checking device state for device em_2 [Jun 12 17:37:22] DEBUG[2919] chan_iax2.c: iax2_devicestate: Found peer. What's device state of em_2? addr=169640569, defaddr=0 maxms=0, lastms=0 [Jun 12 17:37:22] DEBUG[2919] devicestate.c: Changing state for IAX2/em_2 - state 0 (Unknown) [Jun 12 17:37:22] DEBUG[2919] devicestate.c: device 'IAX2/em_2' state '0' [Jun 12 17:37:22] DEBUG[2954] app_queue.c: Device 'IAX2/em_2' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 12 17:37:22] DEBUG[2935] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:37:22] DEBUG[2935] res_config_mysql.c: MySQL RealTime: Update SQL: UPDATE iax_trunk SET `ipaddr` = '10.28.130.121', `port` = '4569', `regseconds` = '1371051442' WHERE `name` = 'em_2' [Jun 12 17:37:22] DEBUG[2935] res_config_mysql.c: MySQL RealTime: Updated 1 rows on table: iax_trunk [Jun 12 17:37:22] DEBUG[2936] chan_iax2.c: schedule decrement of callno used for 10.28.130.121 in 60 seconds [Jun 12 17:37:29] DEBUG[2958] chan_sip.c: = Looking for Call ID: KqCXzLqQUjgRo30uuwVP0-BmQ48BBFdd (Checking From) --From tag QzjYpxQR-57sQwwuTFBIY40vsBCeGSgQ --To-tag [Jun 12 17:37:29] DEBUG[2958] acl.c: For destination '10.28.130.142', our source address is '10.28.130.125'. [Jun 12 17:37:29] DEBUG[2958] chan_sip.c: Setting SIP_TRANSPORT_TCP with address 10.28.130.125:5060 [Jun 12 17:37:29] DEBUG[2958] chan_sip.c: Allocating new SIP dialog for KqCXzLqQUjgRo30uuwVP0-BmQ48BBFdd - REGISTER (No RTP) [Jun 12 17:37:29] DEBUG[2958] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Jun 12 17:37:29] DEBUG[2958] netsock2.c: Splitting '10.28.130.142:52052' into... [Jun 12 17:37:29] DEBUG[2958] netsock2.c: ...host '10.28.130.142' and port '52052'. [Jun 12 17:37:29] DEBUG[2958] netsock2.c: Splitting '10.28.130.125' into... [Jun 12 17:37:29] DEBUG[2958] netsock2.c: ...host '10.28.130.125' and port ''. [Jun 12 17:37:29] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:37:29] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '4200' AND host = 'dynamic' [Jun 12 17:37:29] DEBUG[2958] chan_sip.c: -REALTIME- peer built. Name: 4200. Peer objects: 1 [Jun 12 17:37:29] DEBUG[2958] netsock2.c: Splitting '10.28.130.142' into... [Jun 12 17:37:29] DEBUG[2958] netsock2.c: ...host '10.28.130.142' and port ''. [Jun 12 17:37:29] DEBUG[2958] netsock2.c: Splitting '0.0.0.0' into... [Jun 12 17:37:29] DEBUG[2958] netsock2.c: ...host '0.0.0.0' and port ''. [Jun 12 17:37:29] DEBUG[2958] chan_sip.c: -REALTIME- loading peer from database to memory. Name: 4200. Peer objects: 1 [Jun 12 17:37:29] DEBUG[2958] chan_sip.c: Trying to put 'SIP/2.0 401' onto TCP socket destined for 10.28.130.142:52052 [Jun 12 17:37:29] DEBUG[2958] chan_sip.c: Destroying SIP peer 4200 [Jun 12 17:37:29] DEBUG[2958] chan_sip.c: -REALTIME- peer Destroyed. Name: 4200. Realtime Peer objects: 0 [Jun 12 17:37:29] DEBUG[2958] chan_sip.c: = Looking for Call ID: KqCXzLqQUjgRo30uuwVP0-BmQ48BBFdd (Checking From) --From tag QzjYpxQR-57sQwwuTFBIY40vsBCeGSgQ --To-tag [Jun 12 17:37:29] DEBUG[2958] netsock2.c: Splitting '10.28.130.125:5060' into... [Jun 12 17:37:29] DEBUG[2958] netsock2.c: ...host '10.28.130.125' and port '5060'. [Jun 12 17:37:29] DEBUG[2958] netsock2.c: Splitting '10.28.130.125:5060' into... [Jun 12 17:37:29] DEBUG[2958] netsock2.c: ...host '10.28.130.125' and port '5060'. [Jun 12 17:37:29] DEBUG[2958] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Jun 12 17:37:29] DEBUG[2958] netsock2.c: Splitting '10.28.130.142:52052' into... [Jun 12 17:37:29] DEBUG[2958] netsock2.c: ...host '10.28.130.142' and port '52052'. [Jun 12 17:37:29] DEBUG[2958] netsock2.c: Splitting '10.28.130.125' into... [Jun 12 17:37:29] DEBUG[2958] netsock2.c: ...host '10.28.130.125' and port ''. [Jun 12 17:37:29] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:37:29] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '4200' AND host = 'dynamic' [Jun 12 17:37:29] DEBUG[2958] chan_sip.c: -REALTIME- peer built. Name: 4200. Peer objects: 1 [Jun 12 17:37:29] DEBUG[2958] netsock2.c: Splitting '10.28.130.142' into... [Jun 12 17:37:29] DEBUG[2958] netsock2.c: ...host '10.28.130.142' and port ''. [Jun 12 17:37:29] DEBUG[2958] netsock2.c: Splitting '0.0.0.0' into... [Jun 12 17:37:29] DEBUG[2958] netsock2.c: ...host '0.0.0.0' and port ''. [Jun 12 17:37:29] DEBUG[2958] chan_sip.c: -REALTIME- loading peer from database to memory. Name: 4200. Peer objects: 1 [Jun 12 17:37:29] DEBUG[2958] chan_sip.c: Store REGISTER's src-IP:port for call routing. [Jun 12 17:37:29] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:37:29] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Update SQL: UPDATE sipexten SET `ipaddr` = '10.28.130.142', `port` = '52052', `regseconds` = '1371051749', `defaultuser` = '4200', `useragent` = 'Digium D40 1_0_5_46476', `lastms` = '0', `fullcontact` = 'sip:4200@10.28.130.142:5060^3Btransport=TCP^3Bob' WHERE `name` = '4200' [Jun 12 17:37:29] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Updated 1 rows on table: sipexten [Jun 12 17:37:29] DEBUG[2958] chan_sip.c: Trying to put 'SIP/2.0 200' onto TCP socket destined for 10.28.130.142:52052 [Jun 12 17:37:29] DEBUG[2919] devicestate.c: No provider found, checking channel drivers for SIP - 4200 [Jun 12 17:37:29] DEBUG[2919] chan_sip.c: Checking device state for peer 4200 [Jun 12 17:37:29] DEBUG[2958] chan_sip.c: Destroying SIP peer 4200 [Jun 12 17:37:29] DEBUG[2958] chan_sip.c: -REALTIME- peer Destroyed. Name: 4200. Realtime Peer objects: 0 [Jun 12 17:37:29] DEBUG[2919] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:37:29] DEBUG[2919] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '4200' AND host = 'dynamic' [Jun 12 17:37:29] DEBUG[2919] chan_sip.c: -REALTIME- peer built. Name: 4200. Peer objects: 1 [Jun 12 17:37:29] DEBUG[2919] netsock2.c: Splitting '10.28.130.142' into... [Jun 12 17:37:29] DEBUG[2919] netsock2.c: ...host '10.28.130.142' and port ''. [Jun 12 17:37:29] DEBUG[2919] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port. [Jun 12 17:37:29] DEBUG[2919] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port. [Jun 12 17:37:29] DEBUG[2919] chan_sip.c: -REALTIME- loading peer from database to memory. Name: 4200. Peer objects: 1 [Jun 12 17:37:29] DEBUG[2919] chan_sip.c: Destroying SIP peer 4200 [Jun 12 17:37:29] DEBUG[2919] chan_sip.c: -REALTIME- peer Destroyed. Name: 4200. Realtime Peer objects: 0 [Jun 12 17:37:29] DEBUG[2919] devicestate.c: Changing state for SIP/4200 - state 1 (Not in use) [Jun 12 17:37:29] DEBUG[2919] devicestate.c: device 'SIP/4200' state '1' [Jun 12 17:37:29] DEBUG[2954] app_queue.c: Device 'SIP/4200' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 12 17:37:29] DEBUG[2958] chan_sip.c: = Looking for Call ID: uwiec7Gzqz4pRyi6zfoC1riEkLQjJ1uh (Checking From) --From tag cPHZcjbu6nnxwIyHWE4cdSAKvteMMdL9 --To-tag [Jun 12 17:37:29] DEBUG[2958] acl.c: For destination '10.28.130.142', our source address is '10.28.130.125'. [Jun 12 17:37:29] DEBUG[2958] chan_sip.c: Setting SIP_TRANSPORT_TCP with address 10.28.130.125:5060 [Jun 12 17:37:29] DEBUG[2958] chan_sip.c: Allocating new SIP dialog for uwiec7Gzqz4pRyi6zfoC1riEkLQjJ1uh - SUBSCRIBE (No RTP) [Jun 12 17:37:29] DEBUG[2958] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Jun 12 17:37:29] DEBUG[2958] netsock2.c: Splitting '10.28.130.142:52052' into... [Jun 12 17:37:29] DEBUG[2958] netsock2.c: ...host '10.28.130.142' and port '52052'. [Jun 12 17:37:29] DEBUG[2958] chan_sip.c: build_route: Contact hop: "4200" [Jun 12 17:37:29] DEBUG[2958] netsock2.c: Splitting '10.28.130.125' into... [Jun 12 17:37:29] DEBUG[2958] netsock2.c: ...host '10.28.130.125' and port ''. [Jun 12 17:37:29] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:37:29] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '4200' AND host = 'dynamic' [Jun 12 17:37:29] DEBUG[2958] chan_sip.c: -REALTIME- peer built. Name: 4200. Peer objects: 1 [Jun 12 17:37:29] DEBUG[2958] netsock2.c: Splitting '10.28.130.142' into... [Jun 12 17:37:29] DEBUG[2958] netsock2.c: ...host '10.28.130.142' and port ''. [Jun 12 17:37:29] DEBUG[2958] netsock2.c: Splitting '0.0.0.0' into... [Jun 12 17:37:29] DEBUG[2958] netsock2.c: ...host '0.0.0.0' and port ''. [Jun 12 17:37:29] DEBUG[2958] chan_sip.c: -REALTIME- loading peer from database to memory. Name: 4200. Peer objects: 1 [Jun 12 17:37:29] DEBUG[2958] chan_sip.c: Trying to put 'SIP/2.0 401' onto TCP socket destined for 10.28.130.142:52052 [Jun 12 17:37:29] DEBUG[2958] chan_sip.c: Destroying SIP peer 4200 [Jun 12 17:37:29] DEBUG[2958] chan_sip.c: -REALTIME- peer Destroyed. Name: 4200. Realtime Peer objects: 0 [Jun 12 17:37:29] DEBUG[2958] chan_sip.c: = Looking for Call ID: uwiec7Gzqz4pRyi6zfoC1riEkLQjJ1uh (Checking From) --From tag cPHZcjbu6nnxwIyHWE4cdSAKvteMMdL9 --To-tag [Jun 12 17:37:29] DEBUG[2958] netsock2.c: Splitting '10.28.130.125:5060' into... [Jun 12 17:37:29] DEBUG[2958] netsock2.c: ...host '10.28.130.125' and port '5060'. [Jun 12 17:37:29] DEBUG[2958] netsock2.c: Splitting '10.28.130.125:5060' into... [Jun 12 17:37:29] DEBUG[2958] netsock2.c: ...host '10.28.130.125' and port '5060'. [Jun 12 17:37:29] DEBUG[2958] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Jun 12 17:37:29] DEBUG[2958] netsock2.c: Splitting '10.28.130.142:52052' into... [Jun 12 17:37:29] DEBUG[2958] netsock2.c: ...host '10.28.130.142' and port '52052'. [Jun 12 17:37:29] DEBUG[2958] chan_sip.c: build_route: Retaining previous route: [Jun 12 17:37:29] DEBUG[2958] netsock2.c: Splitting '10.28.130.125' into... [Jun 12 17:37:29] DEBUG[2958] netsock2.c: ...host '10.28.130.125' and port ''. [Jun 12 17:37:29] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:37:29] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '4200' AND host = 'dynamic' [Jun 12 17:37:29] DEBUG[2958] chan_sip.c: -REALTIME- peer built. Name: 4200. Peer objects: 1 [Jun 12 17:37:29] DEBUG[2958] netsock2.c: Splitting '10.28.130.142' into... [Jun 12 17:37:29] DEBUG[2958] netsock2.c: ...host '10.28.130.142' and port ''. [Jun 12 17:37:29] DEBUG[2958] netsock2.c: Splitting '0.0.0.0' into... [Jun 12 17:37:29] DEBUG[2958] netsock2.c: ...host '0.0.0.0' and port ''. [Jun 12 17:37:29] DEBUG[2958] chan_sip.c: -REALTIME- loading peer from database to memory. Name: 4200. Peer objects: 1 [Jun 12 17:37:29] DEBUG[2958] chan_sip.c: Trying to put 'SIP/2.0 404' onto TCP socket destined for 10.28.130.142:52052 [Jun 12 17:37:29] NOTICE[2958] chan_sip.c: Received SIP subscribe for peer without mailbox: 4200 [Jun 12 17:37:29] DEBUG[2958] chan_sip.c: Destroying SIP peer 4200 [Jun 12 17:37:29] DEBUG[2958] chan_sip.c: -REALTIME- peer Destroyed. Name: 4200. Realtime Peer objects: 0 [Jun 12 17:37:29] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:37:29] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '10.28.130.121' AND host = 'dynamic' [Jun 12 17:37:29] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:37:29] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '10.28.130.121' [Jun 12 17:37:29] DEBUG[2928] chan_sip.c: SIP Registry 10.28.130.121: refcount now 3 [Jun 12 17:37:29] DEBUG[2928] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:37:29] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:37:29] DEBUG[2928] chan_sip.c: SIP Registry 10.28.130.121: refcount now 2 [Jun 12 17:37:29] DEBUG[2928] chan_sip.c: Allocating new SIP dialog for 0df587045630ad970a2a21583d853f9f@10.28.130.125 - REGISTER (No RTP) [Jun 12 17:37:29] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:37:29] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '10.28.130.121' AND host = 'dynamic' [Jun 12 17:37:29] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:37:29] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '10.28.130.121' [Jun 12 17:37:29] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:37:29] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '10.28.130.121' AND host = 'dynamic' [Jun 12 17:37:29] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:37:29] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '10.28.130.121' [Jun 12 17:37:29] DEBUG[2928] chan_sip.c: SIP Registry 10.28.130.121: refcount now 3 [Jun 12 17:37:29] DEBUG[2928] acl.c: For destination '10.28.130.121', our source address is '10.28.130.125'. [Jun 12 17:37:29] DEBUG[2928] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.28.130.125:5060 [Jun 12 17:37:29] DEBUG[2928] chan_sip.c: SIP Registry 10.28.130.121: refcount now 4 [Jun 12 17:37:29] DEBUG[2928] chan_sip.c: Scheduled a registration timeout for 10.28.130.121 id #48812 [Jun 12 17:37:29] DEBUG[2928] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:37:29] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:37:29] DEBUG[2928] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:37:29] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:37:29] DEBUG[2928] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:37:29] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:37:29] DEBUG[2928] chan_sip.c: Initializing initreq for method REGISTER - callid 0df587045630ad970a2a21583d853f9f@10.28.130.125 [Jun 12 17:37:29] DEBUG[2928] chan_sip.c: REGISTER attempt 1 to 2997@10.28.130.121 [Jun 12 17:37:29] DEBUG[2928] chan_sip.c: Trying to put 'REGISTER si' onto UDP socket destined for 10.28.130.121:5060 [Jun 12 17:37:29] DEBUG[2928] chan_sip.c: SIP Registry 10.28.130.121: refcount now 3 [Jun 12 17:37:29] DEBUG[2928] chan_sip.c: Destroying SIP dialog uwiec7Gzqz4pRyi6zfoC1riEkLQjJ1uh [Jun 12 17:37:29] DEBUG[2928] chan_sip.c: = Looking for Call ID: 0df587045630ad970a2a21583d853f9f@10.28.130.125 (Checking To) --From tag as3874c831 --To-tag as11d2dec3 [Jun 12 17:37:29] DEBUG[2928] chan_sip.c: Stopping retransmission on '0df587045630ad970a2a21583d853f9f@10.28.130.125' of Request 10012: Match Found [Jun 12 17:37:29] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:37:29] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '10.28.130.121' AND host = 'dynamic' [Jun 12 17:37:29] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:37:29] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '10.28.130.121' [Jun 12 17:37:29] DEBUG[2928] chan_sip.c: SIP Registry 10.28.130.121: refcount now 4 [Jun 12 17:37:29] DEBUG[2928] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:37:29] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:37:29] DEBUG[2928] chan_sip.c: SIP Registry 10.28.130.121: refcount now 3 [Jun 12 17:37:29] DEBUG[2928] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:37:29] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:37:29] DEBUG[2928] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:37:29] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:37:29] DEBUG[2928] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:37:29] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:37:29] DEBUG[2928] chan_sip.c: Initializing already initialized SIP dialog 0df587045630ad970a2a21583d853f9f@10.28.130.125 (presumably reinvite) [Jun 12 17:37:29] DEBUG[2928] chan_sip.c: REGISTER attempt 2 to 2997@10.28.130.121 [Jun 12 17:37:29] DEBUG[2928] chan_sip.c: Trying to put 'REGISTER si' onto UDP socket destined for 10.28.130.121:5060 [Jun 12 17:37:29] DEBUG[2928] chan_sip.c: = Looking for Call ID: 0df587045630ad970a2a21583d853f9f@10.28.130.125 (Checking To) --From tag as43089833 --To-tag as11d2dec3 [Jun 12 17:37:29] DEBUG[2928] chan_sip.c: Stopping retransmission on '0df587045630ad970a2a21583d853f9f@10.28.130.125' of Request 10013: Match Found [Jun 12 17:37:29] DEBUG[2928] chan_sip.c: Registration successful [Jun 12 17:37:29] DEBUG[2928] chan_sip.c: Cancelling timeout 48812 [Jun 12 17:37:29] DEBUG[2928] chan_sip.c: SIP Registry 10.28.130.121: refcount now 2 [Jun 12 17:37:29] DEBUG[2928] chan_sip.c: SIP Registry 10.28.130.121: refcount now 1 [Jun 12 17:37:29] DEBUG[2928] chan_sip.c: SIP Registry 10.28.130.121: refcount now 2 [Jun 12 17:37:30] DEBUG[2958] chan_sip.c: = Looking for Call ID: QKCVqK.VQO6IrAq881Qe8pxUpLw4HnGq (Checking From) --From tag xA9LFZWX-Yo58yf0asaJLA8C1mABznnS --To-tag [Jun 12 17:37:30] DEBUG[2958] acl.c: For destination '10.28.130.142', our source address is '10.28.130.125'. [Jun 12 17:37:30] DEBUG[2958] chan_sip.c: Setting SIP_TRANSPORT_TCP with address 10.28.130.125:5060 [Jun 12 17:37:30] DEBUG[2958] chan_sip.c: Allocating new SIP dialog for QKCVqK.VQO6IrAq881Qe8pxUpLw4HnGq - SUBSCRIBE (No RTP) [Jun 12 17:37:30] DEBUG[2958] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Jun 12 17:37:30] DEBUG[2958] netsock2.c: Splitting '10.28.130.142:52052' into... [Jun 12 17:37:30] DEBUG[2958] netsock2.c: ...host '10.28.130.142' and port '52052'. [Jun 12 17:37:30] DEBUG[2958] chan_sip.c: build_route: Contact hop: "4200" [Jun 12 17:37:30] DEBUG[2958] netsock2.c: Splitting '10.28.130.125' into... [Jun 12 17:37:30] DEBUG[2958] netsock2.c: ...host '10.28.130.125' and port ''. [Jun 12 17:37:30] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:37:30] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '4200' AND host = 'dynamic' [Jun 12 17:37:30] DEBUG[2958] chan_sip.c: -REALTIME- peer built. Name: 4200. Peer objects: 1 [Jun 12 17:37:30] DEBUG[2958] netsock2.c: Splitting '10.28.130.142' into... [Jun 12 17:37:30] DEBUG[2958] netsock2.c: ...host '10.28.130.142' and port ''. [Jun 12 17:37:30] DEBUG[2958] netsock2.c: Splitting '0.0.0.0' into... [Jun 12 17:37:30] DEBUG[2958] netsock2.c: ...host '0.0.0.0' and port ''. [Jun 12 17:37:30] DEBUG[2958] chan_sip.c: -REALTIME- loading peer from database to memory. Name: 4200. Peer objects: 1 [Jun 12 17:37:30] DEBUG[2958] chan_sip.c: Trying to put 'SIP/2.0 401' onto TCP socket destined for 10.28.130.142:52052 [Jun 12 17:37:30] DEBUG[2958] chan_sip.c: Destroying SIP peer 4200 [Jun 12 17:37:30] DEBUG[2958] chan_sip.c: -REALTIME- peer Destroyed. Name: 4200. Realtime Peer objects: 0 [Jun 12 17:37:30] DEBUG[2958] chan_sip.c: = Looking for Call ID: QKCVqK.VQO6IrAq881Qe8pxUpLw4HnGq (Checking From) --From tag xA9LFZWX-Yo58yf0asaJLA8C1mABznnS --To-tag [Jun 12 17:37:30] DEBUG[2958] netsock2.c: Splitting '10.28.130.125:5060' into... [Jun 12 17:37:30] DEBUG[2958] netsock2.c: ...host '10.28.130.125' and port '5060'. [Jun 12 17:37:30] DEBUG[2958] netsock2.c: Splitting '10.28.130.125:5060' into... [Jun 12 17:37:30] DEBUG[2958] netsock2.c: ...host '10.28.130.125' and port '5060'. [Jun 12 17:37:30] DEBUG[2958] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Jun 12 17:37:30] DEBUG[2958] netsock2.c: Splitting '10.28.130.142:52052' into... [Jun 12 17:37:30] DEBUG[2958] netsock2.c: ...host '10.28.130.142' and port '52052'. [Jun 12 17:37:30] DEBUG[2958] chan_sip.c: build_route: Retaining previous route: [Jun 12 17:37:30] DEBUG[2958] netsock2.c: Splitting '10.28.130.125' into... [Jun 12 17:37:30] DEBUG[2958] netsock2.c: ...host '10.28.130.125' and port ''. [Jun 12 17:37:30] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:37:30] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '4200' AND host = 'dynamic' [Jun 12 17:37:30] DEBUG[2958] chan_sip.c: -REALTIME- peer built. Name: 4200. Peer objects: 1 [Jun 12 17:37:30] DEBUG[2958] netsock2.c: Splitting '10.28.130.142' into... [Jun 12 17:37:30] DEBUG[2958] netsock2.c: ...host '10.28.130.142' and port ''. [Jun 12 17:37:30] DEBUG[2958] netsock2.c: Splitting '0.0.0.0' into... [Jun 12 17:37:30] DEBUG[2958] netsock2.c: ...host '0.0.0.0' and port ''. [Jun 12 17:37:30] DEBUG[2958] chan_sip.c: -REALTIME- loading peer from database to memory. Name: 4200. Peer objects: 1 [Jun 12 17:37:30] DEBUG[2958] netsock2.c: Splitting '10.28.130.125:5060' into... [Jun 12 17:37:30] DEBUG[2958] netsock2.c: ...host '10.28.130.125' and port ''. [Jun 12 17:37:30] DEBUG[2958] netsock2.c: Splitting '10.28.130.125' into... [Jun 12 17:37:30] DEBUG[2958] netsock2.c: ...host '10.28.130.125' and port ''. [Jun 12 17:37:30] DEBUG[2958] chan_sip.c: Trying to put 'SIP/2.0 404' onto TCP socket destined for 10.28.130.142:52052 [Jun 12 17:37:30] DEBUG[2958] chan_sip.c: Destroying SIP peer 4200 [Jun 12 17:37:30] DEBUG[2958] chan_sip.c: -REALTIME- peer Destroyed. Name: 4200. Realtime Peer objects: 0 [Jun 12 17:37:30] DEBUG[2928] chan_sip.c: Destroying SIP dialog QKCVqK.VQO6IrAq881Qe8pxUpLw4HnGq [Jun 12 17:37:32] DEBUG[2930] chan_iax2.c: ip callno count decremented to 1 for 10.28.130.121 [Jun 12 17:38:01] DEBUG[2928] chan_sip.c: Auto destroying SIP dialog 'KqCXzLqQUjgRo30uuwVP0-BmQ48BBFdd' [Jun 12 17:38:01] DEBUG[2928] chan_sip.c: Destroying SIP dialog KqCXzLqQUjgRo30uuwVP0-BmQ48BBFdd [Jun 12 17:38:01] DEBUG[2928] chan_sip.c: Auto destroying SIP dialog '0df587045630ad970a2a21583d853f9f@10.28.130.125' [Jun 12 17:38:01] DEBUG[2928] chan_sip.c: Destroying SIP dialog 0df587045630ad970a2a21583d853f9f@10.28.130.125 [Jun 12 17:38:12] VERBOSE[2939] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: REGREQ [Jun 12 17:38:12] VERBOSE[2939] chan_iax2.c: Timestamp: 00001ms SCall: 00709 DCall: 00000 [10.28.130.121:4569] [Jun 12 17:38:12] VERBOSE[2939] chan_iax2.c: USERNAME : em_2 [Jun 12 17:38:12] VERBOSE[2939] chan_iax2.c: REFRESH : 60 [Jun 12 17:38:12] VERBOSE[2939] chan_iax2.c: [Jun 12 17:38:12] VERBOSE[2939] chan_iax2.c: Tx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: CTOKEN [Jun 12 17:38:12] VERBOSE[2939] chan_iax2.c: Timestamp: 00001ms SCall: 00001 DCall: 00709 [10.28.130.121:4569] [Jun 12 17:38:12] VERBOSE[2939] chan_iax2.c: CALLTOKEN : 51 bytes [Jun 12 17:38:12] VERBOSE[2939] chan_iax2.c: [Jun 12 17:38:12] VERBOSE[2940] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: REGREQ [Jun 12 17:38:12] VERBOSE[2940] chan_iax2.c: Timestamp: 00002ms SCall: 00709 DCall: 00000 [10.28.130.121:4569] [Jun 12 17:38:12] VERBOSE[2940] chan_iax2.c: USERNAME : em_2 [Jun 12 17:38:12] VERBOSE[2940] chan_iax2.c: REFRESH : 60 [Jun 12 17:38:12] VERBOSE[2940] chan_iax2.c: CALLTOKEN : 51 bytes [Jun 12 17:38:12] VERBOSE[2940] chan_iax2.c: [Jun 12 17:38:12] DEBUG[2940] chan_iax2.c: ip callno count incremented to 2 for 10.28.130.121 [Jun 12 17:38:12] DEBUG[2940] chan_iax2.c: Creating new call structure 1427 [Jun 12 17:38:12] DEBUG[2940] chan_iax2.c: Received packet 0, (6, 13) [Jun 12 17:38:12] DEBUG[2940] chan_iax2.c: IAX subclass 13 received [Jun 12 17:38:12] DEBUG[2940] chan_iax2.c: For call=1427, set last=2 [Jun 12 17:38:12] DEBUG[2919] devicestate.c: No provider found, checking channel drivers for IAX2 - em_2 [Jun 12 17:38:12] DEBUG[2919] chan_iax2.c: Checking device state for device em_2 [Jun 12 17:38:12] DEBUG[2919] chan_iax2.c: iax2_devicestate: Found peer. What's device state of em_2? addr=169640569, defaddr=0 maxms=0, lastms=0 [Jun 12 17:38:12] DEBUG[2919] devicestate.c: Changing state for IAX2/em_2 - state 0 (Unknown) [Jun 12 17:38:12] DEBUG[2919] devicestate.c: device 'IAX2/em_2' state '0' [Jun 12 17:38:12] DEBUG[2929] chan_iax2.c: Sending 17 on 1427/709 to 10.28.130.121:4569 [Jun 12 17:38:12] VERBOSE[2929] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: REGAUTH [Jun 12 17:38:12] VERBOSE[2929] chan_iax2.c: Timestamp: 00017ms SCall: 01427 DCall: 00709 [10.28.130.121:4569] [Jun 12 17:38:12] VERBOSE[2929] chan_iax2.c: AUTHMETHODS : 3 [Jun 12 17:38:12] VERBOSE[2929] chan_iax2.c: CHALLENGE : \x33\x31\x30\x38\x39\x35\x30\x37\x34 [Jun 12 17:38:12] VERBOSE[2929] chan_iax2.c: USERNAME : em_2 [Jun 12 17:38:12] VERBOSE[2929] chan_iax2.c: [Jun 12 17:38:12] DEBUG[2954] app_queue.c: Device 'IAX2/em_2' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 12 17:38:12] VERBOSE[2931] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: REGREQ [Jun 12 17:38:12] VERBOSE[2931] chan_iax2.c: Timestamp: 00003ms SCall: 00709 DCall: 01427 [10.28.130.121:4569] [Jun 12 17:38:12] VERBOSE[2931] chan_iax2.c: USERNAME : em_2 [Jun 12 17:38:12] VERBOSE[2931] chan_iax2.c: REFRESH : 60 [Jun 12 17:38:12] VERBOSE[2931] chan_iax2.c: MD5 RESULT : 4992c7e65c8986987a64cf38b69d3677 [Jun 12 17:38:12] VERBOSE[2931] chan_iax2.c: [Jun 12 17:38:12] DEBUG[2931] chan_iax2.c: Received packet 1, (6, 13) [Jun 12 17:38:12] DEBUG[2931] chan_iax2.c: Cancelling transmission of packet 0 [Jun 12 17:38:12] DEBUG[2931] chan_iax2.c: IAX subclass 13 received [Jun 12 17:38:12] DEBUG[2931] chan_iax2.c: For call=1427, set last=3 [Jun 12 17:38:12] DEBUG[2919] devicestate.c: No provider found, checking channel drivers for IAX2 - em_2 [Jun 12 17:38:12] DEBUG[2919] chan_iax2.c: Checking device state for device em_2 [Jun 12 17:38:12] DEBUG[2919] chan_iax2.c: iax2_devicestate: Found peer. What's device state of em_2? addr=169640569, defaddr=0 maxms=0, lastms=0 [Jun 12 17:38:12] DEBUG[2919] devicestate.c: Changing state for IAX2/em_2 - state 0 (Unknown) [Jun 12 17:38:12] DEBUG[2919] devicestate.c: device 'IAX2/em_2' state '0' [Jun 12 17:38:12] DEBUG[2954] app_queue.c: Device 'IAX2/em_2' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 12 17:38:12] DEBUG[2931] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:38:12] DEBUG[2931] res_config_mysql.c: MySQL RealTime: Update SQL: UPDATE iax_trunk SET `ipaddr` = '10.28.130.121', `port` = '4569', `regseconds` = '1371051492' WHERE `name` = 'em_2' [Jun 12 17:38:12] DEBUG[2931] res_config_mysql.c: MySQL RealTime: Updated 1 rows on table: iax_trunk [Jun 12 17:38:12] DEBUG[2929] chan_iax2.c: Sending 20 on 1427/709 to 10.28.130.121:4569 [Jun 12 17:38:12] VERBOSE[2929] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: REGACK [Jun 12 17:38:12] VERBOSE[2929] chan_iax2.c: Timestamp: 00020ms SCall: 01427 DCall: 00709 [10.28.130.121:4569] [Jun 12 17:38:12] VERBOSE[2929] chan_iax2.c: USERNAME : em_2 [Jun 12 17:38:12] VERBOSE[2929] chan_iax2.c: DATE TIME : 2013-06-12 17:38:12 [Jun 12 17:38:12] VERBOSE[2929] chan_iax2.c: REFRESH : 60 [Jun 12 17:38:12] VERBOSE[2929] chan_iax2.c: APPARENT ADDRES : IPV4 10.28.130.121:4569 [Jun 12 17:38:12] VERBOSE[2929] chan_iax2.c: [Jun 12 17:38:12] VERBOSE[2932] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK [Jun 12 17:38:12] VERBOSE[2932] chan_iax2.c: Timestamp: 00020ms SCall: 00709 DCall: 01427 [10.28.130.121:4569] [Jun 12 17:38:12] DEBUG[2932] chan_iax2.c: Received packet 2, (6, 4) [Jun 12 17:38:12] DEBUG[2932] chan_iax2.c: Cancelling transmission of packet 1 [Jun 12 17:38:12] DEBUG[2932] chan_iax2.c: Really destroying 1427, having been acked on final message [Jun 12 17:38:12] DEBUG[2932] chan_iax2.c: schedule decrement of callno used for 10.28.130.121 in 60 seconds [Jun 12 17:38:22] DEBUG[2930] chan_iax2.c: ip callno count decremented to 1 for 10.28.130.121 [Jun 12 17:38:34] DEBUG[2928] chan_sip.c: = Looking for Call ID: 3168827b0300bc7455c86a247f978468@10.28.130.121 (Checking From) --From tag as1e0328b1 --To-tag [Jun 12 17:38:34] DEBUG[2928] acl.c: For destination '10.28.130.121', our source address is '10.28.130.125'. [Jun 12 17:38:34] DEBUG[2928] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.28.130.125:5060 [Jun 12 17:38:34] DEBUG[2928] chan_sip.c: Allocating new SIP dialog for 3168827b0300bc7455c86a247f978468@10.28.130.121 - REGISTER (No RTP) [Jun 12 17:38:34] DEBUG[2928] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Jun 12 17:38:34] DEBUG[2928] netsock2.c: Splitting '10.28.130.121:5060' into... [Jun 12 17:38:34] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port '5060'. [Jun 12 17:38:34] DEBUG[2928] netsock2.c: Splitting '10.28.130.125' into... [Jun 12 17:38:34] DEBUG[2928] netsock2.c: ...host '10.28.130.125' and port ''. [Jun 12 17:38:34] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:38:34] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '4299' AND host = 'dynamic' [Jun 12 17:38:34] DEBUG[2928] chan_sip.c: -REALTIME- peer built. Name: 4299. Peer objects: 1 [Jun 12 17:38:34] DEBUG[2928] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:38:34] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:38:34] DEBUG[2928] netsock2.c: Splitting '0.0.0.0' into... [Jun 12 17:38:34] DEBUG[2928] netsock2.c: ...host '0.0.0.0' and port ''. [Jun 12 17:38:34] DEBUG[2928] chan_sip.c: -REALTIME- loading peer from database to memory. Name: 4299. Peer objects: 1 [Jun 12 17:38:34] DEBUG[2928] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.28.130.121:5060 [Jun 12 17:38:34] DEBUG[2928] chan_sip.c: Destroying SIP peer 4299 [Jun 12 17:38:34] DEBUG[2928] chan_sip.c: -REALTIME- peer Destroyed. Name: 4299. Realtime Peer objects: 0 [Jun 12 17:38:34] DEBUG[2928] chan_sip.c: = Looking for Call ID: 3168827b0300bc7455c86a247f978468@10.28.130.121 (Checking From) --From tag as1654f5e2 --To-tag [Jun 12 17:38:34] DEBUG[2928] netsock2.c: Splitting '10.28.130.125' into... [Jun 12 17:38:34] DEBUG[2928] netsock2.c: ...host '10.28.130.125' and port ''. [Jun 12 17:38:34] DEBUG[2928] netsock2.c: Splitting '10.28.130.125' into... [Jun 12 17:38:34] DEBUG[2928] netsock2.c: ...host '10.28.130.125' and port ''. [Jun 12 17:38:34] DEBUG[2928] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Jun 12 17:38:34] DEBUG[2928] netsock2.c: Splitting '10.28.130.121:5060' into... [Jun 12 17:38:34] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port '5060'. [Jun 12 17:38:34] DEBUG[2928] netsock2.c: Splitting '10.28.130.125' into... [Jun 12 17:38:34] DEBUG[2928] netsock2.c: ...host '10.28.130.125' and port ''. [Jun 12 17:38:34] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:38:34] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '4299' AND host = 'dynamic' [Jun 12 17:38:34] DEBUG[2928] chan_sip.c: -REALTIME- peer built. Name: 4299. Peer objects: 1 [Jun 12 17:38:34] DEBUG[2928] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:38:34] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:38:34] DEBUG[2928] netsock2.c: Splitting '0.0.0.0' into... [Jun 12 17:38:34] DEBUG[2928] netsock2.c: ...host '0.0.0.0' and port ''. [Jun 12 17:38:34] DEBUG[2928] chan_sip.c: -REALTIME- loading peer from database to memory. Name: 4299. Peer objects: 1 [Jun 12 17:38:34] DEBUG[2928] chan_sip.c: Store REGISTER's src-IP:port for call routing. [Jun 12 17:38:34] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:38:34] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Update SQL: UPDATE sipexten SET `ipaddr` = '10.28.130.121', `port` = '5060', `regseconds` = '1371051634', `defaultuser` = '4299', `useragent` = 'Asterisk PBX 1.8.14.1', `lastms` = '0', `fullcontact` = 'sip:s@10.28.130.121:5060' WHERE `name` = '4299' [Jun 12 17:38:34] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Updated 1 rows on table: sipexten [Jun 12 17:38:34] DEBUG[2928] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.28.130.121:5060 [Jun 12 17:38:34] DEBUG[2919] devicestate.c: No provider found, checking channel drivers for SIP - 4299 [Jun 12 17:38:34] DEBUG[2919] chan_sip.c: Checking device state for peer 4299 [Jun 12 17:38:34] DEBUG[2928] chan_sip.c: Destroying SIP peer 4299 [Jun 12 17:38:34] DEBUG[2928] chan_sip.c: -REALTIME- peer Destroyed. Name: 4299. Realtime Peer objects: 0 [Jun 12 17:38:34] DEBUG[2919] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:38:34] DEBUG[2919] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '4299' AND host = 'dynamic' [Jun 12 17:38:34] DEBUG[2919] chan_sip.c: -REALTIME- peer built. Name: 4299. Peer objects: 1 [Jun 12 17:38:34] DEBUG[2919] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:38:34] DEBUG[2919] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:38:34] DEBUG[2919] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port. [Jun 12 17:38:34] DEBUG[2919] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port. [Jun 12 17:38:34] DEBUG[2919] chan_sip.c: -REALTIME- loading peer from database to memory. Name: 4299. Peer objects: 1 [Jun 12 17:38:34] DEBUG[2919] chan_sip.c: Destroying SIP peer 4299 [Jun 12 17:38:34] DEBUG[2919] chan_sip.c: -REALTIME- peer Destroyed. Name: 4299. Realtime Peer objects: 0 [Jun 12 17:38:34] DEBUG[2919] devicestate.c: Changing state for SIP/4299 - state 1 (Not in use) [Jun 12 17:38:34] DEBUG[2919] devicestate.c: device 'SIP/4299' state '1' [Jun 12 17:38:34] DEBUG[2954] app_queue.c: Device 'SIP/4299' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 12 17:38:57] DEBUG[2958] chan_sip.c: = Looking for Call ID: NMXZ4g.qQQj-B5t1kYGfgf.N5voQ2Tlu (Checking From) --From tag AFUTFdSU98-nBW--eVfmxIJSxGcvzffh --To-tag [Jun 12 17:38:57] DEBUG[2958] acl.c: For destination '10.28.130.142', our source address is '10.28.130.125'. [Jun 12 17:38:57] DEBUG[2958] chan_sip.c: Setting SIP_TRANSPORT_TCP with address 10.28.130.125:5060 [Jun 12 17:38:57] DEBUG[2958] chan_sip.c: Allocating new SIP dialog for NMXZ4g.qQQj-B5t1kYGfgf.N5voQ2Tlu - SUBSCRIBE (No RTP) [Jun 12 17:38:57] DEBUG[2958] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Jun 12 17:38:57] DEBUG[2958] netsock2.c: Splitting '10.28.130.142:52052' into... [Jun 12 17:38:57] DEBUG[2958] netsock2.c: ...host '10.28.130.142' and port '52052'. [Jun 12 17:38:57] DEBUG[2958] chan_sip.c: build_route: Contact hop: "4200" [Jun 12 17:38:57] DEBUG[2958] netsock2.c: Splitting '10.28.130.125' into... [Jun 12 17:38:57] DEBUG[2958] netsock2.c: ...host '10.28.130.125' and port ''. [Jun 12 17:38:57] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:38:57] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '4200' AND host = 'dynamic' [Jun 12 17:38:57] DEBUG[2958] chan_sip.c: -REALTIME- peer built. Name: 4200. Peer objects: 1 [Jun 12 17:38:57] DEBUG[2958] netsock2.c: Splitting '10.28.130.142' into... [Jun 12 17:38:57] DEBUG[2958] netsock2.c: ...host '10.28.130.142' and port ''. [Jun 12 17:38:57] DEBUG[2958] netsock2.c: Splitting '0.0.0.0' into... [Jun 12 17:38:57] DEBUG[2958] netsock2.c: ...host '0.0.0.0' and port ''. [Jun 12 17:38:57] DEBUG[2958] chan_sip.c: -REALTIME- loading peer from database to memory. Name: 4200. Peer objects: 1 [Jun 12 17:38:57] DEBUG[2958] chan_sip.c: Trying to put 'SIP/2.0 401' onto TCP socket destined for 10.28.130.142:52052 [Jun 12 17:38:57] DEBUG[2958] chan_sip.c: Destroying SIP peer 4200 [Jun 12 17:38:57] DEBUG[2958] chan_sip.c: -REALTIME- peer Destroyed. Name: 4200. Realtime Peer objects: 0 [Jun 12 17:38:57] DEBUG[2958] chan_sip.c: = Looking for Call ID: NMXZ4g.qQQj-B5t1kYGfgf.N5voQ2Tlu (Checking From) --From tag AFUTFdSU98-nBW--eVfmxIJSxGcvzffh --To-tag [Jun 12 17:38:57] DEBUG[2958] netsock2.c: Splitting '10.28.130.125:5060' into... [Jun 12 17:38:57] DEBUG[2958] netsock2.c: ...host '10.28.130.125' and port '5060'. [Jun 12 17:38:57] DEBUG[2958] netsock2.c: Splitting '10.28.130.125:5060' into... [Jun 12 17:38:57] DEBUG[2958] netsock2.c: ...host '10.28.130.125' and port '5060'. [Jun 12 17:38:57] DEBUG[2958] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Jun 12 17:38:57] DEBUG[2958] netsock2.c: Splitting '10.28.130.142:52052' into... [Jun 12 17:38:57] DEBUG[2958] netsock2.c: ...host '10.28.130.142' and port '52052'. [Jun 12 17:38:57] DEBUG[2958] chan_sip.c: build_route: Retaining previous route: [Jun 12 17:38:57] DEBUG[2958] netsock2.c: Splitting '10.28.130.125' into... [Jun 12 17:38:57] DEBUG[2958] netsock2.c: ...host '10.28.130.125' and port ''. [Jun 12 17:38:57] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:38:57] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '4200' AND host = 'dynamic' [Jun 12 17:38:57] DEBUG[2958] chan_sip.c: -REALTIME- peer built. Name: 4200. Peer objects: 1 [Jun 12 17:38:57] DEBUG[2958] netsock2.c: Splitting '10.28.130.142' into... [Jun 12 17:38:57] DEBUG[2958] netsock2.c: ...host '10.28.130.142' and port ''. [Jun 12 17:38:57] DEBUG[2958] netsock2.c: Splitting '0.0.0.0' into... [Jun 12 17:38:57] DEBUG[2958] netsock2.c: ...host '0.0.0.0' and port ''. [Jun 12 17:38:57] DEBUG[2958] chan_sip.c: -REALTIME- loading peer from database to memory. Name: 4200. Peer objects: 1 [Jun 12 17:38:57] DEBUG[2958] chan_sip.c: Trying to put 'SIP/2.0 404' onto TCP socket destined for 10.28.130.142:52052 [Jun 12 17:38:57] NOTICE[2958] chan_sip.c: Received SIP subscribe for peer without mailbox: 4200 [Jun 12 17:38:57] DEBUG[2958] chan_sip.c: Destroying SIP peer 4200 [Jun 12 17:38:57] DEBUG[2958] chan_sip.c: -REALTIME- peer Destroyed. Name: 4200. Realtime Peer objects: 0 [Jun 12 17:38:57] DEBUG[2928] chan_sip.c: Destroying SIP dialog NMXZ4g.qQQj-B5t1kYGfgf.N5voQ2Tlu [Jun 12 17:39:02] VERBOSE[2935] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: REGREQ [Jun 12 17:39:02] VERBOSE[2935] chan_iax2.c: Timestamp: 00008ms SCall: 00751 DCall: 00000 [10.28.130.121:4569] [Jun 12 17:39:02] VERBOSE[2935] chan_iax2.c: USERNAME : em_2 [Jun 12 17:39:02] VERBOSE[2935] chan_iax2.c: REFRESH : 60 [Jun 12 17:39:02] VERBOSE[2935] chan_iax2.c: [Jun 12 17:39:02] VERBOSE[2935] chan_iax2.c: Tx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: CTOKEN [Jun 12 17:39:02] VERBOSE[2935] chan_iax2.c: Timestamp: 00008ms SCall: 00001 DCall: 00751 [10.28.130.121:4569] [Jun 12 17:39:02] VERBOSE[2935] chan_iax2.c: CALLTOKEN : 51 bytes [Jun 12 17:39:02] VERBOSE[2935] chan_iax2.c: [Jun 12 17:39:02] VERBOSE[2936] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: REGREQ [Jun 12 17:39:02] VERBOSE[2936] chan_iax2.c: Timestamp: 00011ms SCall: 00751 DCall: 00000 [10.28.130.121:4569] [Jun 12 17:39:02] VERBOSE[2936] chan_iax2.c: USERNAME : em_2 [Jun 12 17:39:02] VERBOSE[2936] chan_iax2.c: REFRESH : 60 [Jun 12 17:39:02] VERBOSE[2936] chan_iax2.c: CALLTOKEN : 51 bytes [Jun 12 17:39:02] VERBOSE[2936] chan_iax2.c: [Jun 12 17:39:02] DEBUG[2936] chan_iax2.c: ip callno count incremented to 2 for 10.28.130.121 [Jun 12 17:39:02] DEBUG[2936] chan_iax2.c: Creating new call structure 3814 [Jun 12 17:39:02] DEBUG[2936] chan_iax2.c: Received packet 0, (6, 13) [Jun 12 17:39:02] DEBUG[2936] chan_iax2.c: IAX subclass 13 received [Jun 12 17:39:02] DEBUG[2936] chan_iax2.c: For call=3814, set last=11 [Jun 12 17:39:02] DEBUG[2919] devicestate.c: No provider found, checking channel drivers for IAX2 - em_2 [Jun 12 17:39:02] DEBUG[2919] chan_iax2.c: Checking device state for device em_2 [Jun 12 17:39:02] DEBUG[2919] chan_iax2.c: iax2_devicestate: Found peer. What's device state of em_2? addr=169640569, defaddr=0 maxms=0, lastms=0 [Jun 12 17:39:02] DEBUG[2919] devicestate.c: Changing state for IAX2/em_2 - state 0 (Unknown) [Jun 12 17:39:02] DEBUG[2919] devicestate.c: device 'IAX2/em_2' state '0' [Jun 12 17:39:02] DEBUG[2929] chan_iax2.c: Sending 1 on 3814/751 to 10.28.130.121:4569 [Jun 12 17:39:02] VERBOSE[2929] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: REGAUTH [Jun 12 17:39:02] VERBOSE[2929] chan_iax2.c: Timestamp: 00001ms SCall: 03814 DCall: 00751 [10.28.130.121:4569] [Jun 12 17:39:02] VERBOSE[2929] chan_iax2.c: AUTHMETHODS : 3 [Jun 12 17:39:02] VERBOSE[2929] chan_iax2.c: CHALLENGE : \x39\x38\x31\x35\x38\x30\x30\x37 [Jun 12 17:39:02] VERBOSE[2929] chan_iax2.c: USERNAME : em_2 [Jun 12 17:39:02] VERBOSE[2929] chan_iax2.c: [Jun 12 17:39:02] DEBUG[2954] app_queue.c: Device 'IAX2/em_2' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 12 17:39:02] VERBOSE[2937] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: REGREQ [Jun 12 17:39:02] VERBOSE[2937] chan_iax2.c: Timestamp: 00014ms SCall: 00751 DCall: 03814 [10.28.130.121:4569] [Jun 12 17:39:02] VERBOSE[2937] chan_iax2.c: USERNAME : em_2 [Jun 12 17:39:02] VERBOSE[2937] chan_iax2.c: REFRESH : 60 [Jun 12 17:39:02] VERBOSE[2937] chan_iax2.c: MD5 RESULT : c03746ec4d88e9f7e925a7f558b2f81a [Jun 12 17:39:02] VERBOSE[2937] chan_iax2.c: [Jun 12 17:39:02] DEBUG[2937] chan_iax2.c: Received packet 1, (6, 13) [Jun 12 17:39:02] DEBUG[2937] chan_iax2.c: Cancelling transmission of packet 0 [Jun 12 17:39:02] DEBUG[2937] chan_iax2.c: IAX subclass 13 received [Jun 12 17:39:02] DEBUG[2937] chan_iax2.c: For call=3814, set last=14 [Jun 12 17:39:02] DEBUG[2919] devicestate.c: No provider found, checking channel drivers for IAX2 - em_2 [Jun 12 17:39:02] DEBUG[2919] chan_iax2.c: Checking device state for device em_2 [Jun 12 17:39:02] DEBUG[2919] chan_iax2.c: iax2_devicestate: Found peer. What's device state of em_2? addr=169640569, defaddr=0 maxms=0, lastms=0 [Jun 12 17:39:02] DEBUG[2919] devicestate.c: Changing state for IAX2/em_2 - state 0 (Unknown) [Jun 12 17:39:02] DEBUG[2919] devicestate.c: device 'IAX2/em_2' state '0' [Jun 12 17:39:02] DEBUG[2954] app_queue.c: Device 'IAX2/em_2' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 12 17:39:02] DEBUG[2937] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:39:02] DEBUG[2937] res_config_mysql.c: MySQL RealTime: Update SQL: UPDATE iax_trunk SET `ipaddr` = '10.28.130.121', `port` = '4569', `regseconds` = '1371051542' WHERE `name` = 'em_2' [Jun 12 17:39:02] DEBUG[2937] res_config_mysql.c: MySQL RealTime: Updated 1 rows on table: iax_trunk [Jun 12 17:39:02] DEBUG[2929] chan_iax2.c: Sending 4 on 3814/751 to 10.28.130.121:4569 [Jun 12 17:39:02] VERBOSE[2929] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: REGACK [Jun 12 17:39:02] VERBOSE[2929] chan_iax2.c: Timestamp: 00004ms SCall: 03814 DCall: 00751 [10.28.130.121:4569] [Jun 12 17:39:02] VERBOSE[2929] chan_iax2.c: USERNAME : em_2 [Jun 12 17:39:02] VERBOSE[2929] chan_iax2.c: DATE TIME : 2013-06-12 17:39:02 [Jun 12 17:39:02] VERBOSE[2929] chan_iax2.c: REFRESH : 60 [Jun 12 17:39:02] VERBOSE[2929] chan_iax2.c: APPARENT ADDRES : IPV4 10.28.130.121:4569 [Jun 12 17:39:02] VERBOSE[2929] chan_iax2.c: [Jun 12 17:39:02] VERBOSE[2938] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK [Jun 12 17:39:02] VERBOSE[2938] chan_iax2.c: Timestamp: 00004ms SCall: 00751 DCall: 03814 [10.28.130.121:4569] [Jun 12 17:39:02] DEBUG[2938] chan_iax2.c: Received packet 2, (6, 4) [Jun 12 17:39:02] DEBUG[2938] chan_iax2.c: Cancelling transmission of packet 1 [Jun 12 17:39:02] DEBUG[2938] chan_iax2.c: Really destroying 3814, having been acked on final message [Jun 12 17:39:02] DEBUG[2938] chan_iax2.c: schedule decrement of callno used for 10.28.130.121 in 60 seconds [Jun 12 17:39:06] DEBUG[2928] chan_sip.c: Auto destroying SIP dialog '3168827b0300bc7455c86a247f978468@10.28.130.121' [Jun 12 17:39:06] DEBUG[2928] chan_sip.c: Destroying SIP dialog 3168827b0300bc7455c86a247f978468@10.28.130.121 [Jun 12 17:39:12] DEBUG[2930] chan_iax2.c: ip callno count decremented to 1 for 10.28.130.121 [Jun 12 17:39:14] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:39:14] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '10.28.130.121' AND host = 'dynamic' [Jun 12 17:39:14] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:39:14] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '10.28.130.121' [Jun 12 17:39:14] DEBUG[2928] chan_sip.c: SIP Registry 10.28.130.121: refcount now 3 [Jun 12 17:39:14] DEBUG[2928] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:39:14] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:39:14] DEBUG[2928] chan_sip.c: SIP Registry 10.28.130.121: refcount now 2 [Jun 12 17:39:14] DEBUG[2928] chan_sip.c: Allocating new SIP dialog for 0df587045630ad970a2a21583d853f9f@10.28.130.125 - REGISTER (No RTP) [Jun 12 17:39:14] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:39:14] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '10.28.130.121' AND host = 'dynamic' [Jun 12 17:39:14] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:39:14] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '10.28.130.121' [Jun 12 17:39:14] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:39:14] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '10.28.130.121' AND host = 'dynamic' [Jun 12 17:39:14] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:39:14] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '10.28.130.121' [Jun 12 17:39:14] DEBUG[2928] chan_sip.c: SIP Registry 10.28.130.121: refcount now 3 [Jun 12 17:39:14] DEBUG[2928] acl.c: For destination '10.28.130.121', our source address is '10.28.130.125'. [Jun 12 17:39:14] DEBUG[2928] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.28.130.125:5060 [Jun 12 17:39:14] DEBUG[2928] chan_sip.c: SIP Registry 10.28.130.121: refcount now 4 [Jun 12 17:39:14] DEBUG[2928] chan_sip.c: Scheduled a registration timeout for 10.28.130.121 id #48821 [Jun 12 17:39:14] DEBUG[2928] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:39:14] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:39:14] DEBUG[2928] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:39:14] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:39:14] DEBUG[2928] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:39:14] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:39:14] DEBUG[2928] chan_sip.c: Initializing initreq for method REGISTER - callid 0df587045630ad970a2a21583d853f9f@10.28.130.125 [Jun 12 17:39:14] DEBUG[2928] chan_sip.c: REGISTER attempt 1 to 2997@10.28.130.121 [Jun 12 17:39:14] DEBUG[2928] chan_sip.c: Trying to put 'REGISTER si' onto UDP socket destined for 10.28.130.121:5060 [Jun 12 17:39:14] DEBUG[2928] chan_sip.c: SIP Registry 10.28.130.121: refcount now 3 [Jun 12 17:39:14] DEBUG[2928] chan_sip.c: = Looking for Call ID: 0df587045630ad970a2a21583d853f9f@10.28.130.125 (Checking To) --From tag as4e25e84c --To-tag as53a07f2e [Jun 12 17:39:14] DEBUG[2928] chan_sip.c: Stopping retransmission on '0df587045630ad970a2a21583d853f9f@10.28.130.125' of Request 10014: Match Found [Jun 12 17:39:14] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:39:14] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '10.28.130.121' AND host = 'dynamic' [Jun 12 17:39:14] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:39:14] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '10.28.130.121' [Jun 12 17:39:14] DEBUG[2928] chan_sip.c: SIP Registry 10.28.130.121: refcount now 4 [Jun 12 17:39:14] DEBUG[2928] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:39:14] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:39:14] DEBUG[2928] chan_sip.c: SIP Registry 10.28.130.121: refcount now 3 [Jun 12 17:39:14] DEBUG[2928] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:39:14] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:39:14] DEBUG[2928] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:39:14] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:39:14] DEBUG[2928] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:39:14] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:39:14] DEBUG[2928] chan_sip.c: Initializing already initialized SIP dialog 0df587045630ad970a2a21583d853f9f@10.28.130.125 (presumably reinvite) [Jun 12 17:39:14] DEBUG[2928] chan_sip.c: REGISTER attempt 2 to 2997@10.28.130.121 [Jun 12 17:39:14] DEBUG[2928] chan_sip.c: Trying to put 'REGISTER si' onto UDP socket destined for 10.28.130.121:5060 [Jun 12 17:39:14] DEBUG[2928] chan_sip.c: = Looking for Call ID: 0df587045630ad970a2a21583d853f9f@10.28.130.125 (Checking To) --From tag as0fc8b72e --To-tag as53a07f2e [Jun 12 17:39:14] DEBUG[2928] chan_sip.c: Stopping retransmission on '0df587045630ad970a2a21583d853f9f@10.28.130.125' of Request 10015: Match Found [Jun 12 17:39:14] DEBUG[2928] chan_sip.c: Registration successful [Jun 12 17:39:14] DEBUG[2928] chan_sip.c: Cancelling timeout 48821 [Jun 12 17:39:14] DEBUG[2928] chan_sip.c: SIP Registry 10.28.130.121: refcount now 2 [Jun 12 17:39:14] DEBUG[2928] chan_sip.c: SIP Registry 10.28.130.121: refcount now 1 [Jun 12 17:39:14] DEBUG[2928] chan_sip.c: SIP Registry 10.28.130.121: refcount now 2 [Jun 12 17:39:46] DEBUG[2928] chan_sip.c: Auto destroying SIP dialog '0df587045630ad970a2a21583d853f9f@10.28.130.125' [Jun 12 17:39:46] DEBUG[2928] chan_sip.c: Destroying SIP dialog 0df587045630ad970a2a21583d853f9f@10.28.130.125 [Jun 12 17:39:52] VERBOSE[2931] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: REGREQ [Jun 12 17:39:52] VERBOSE[2931] chan_iax2.c: Timestamp: 00013ms SCall: 02293 DCall: 00000 [10.28.130.121:4569] [Jun 12 17:39:52] VERBOSE[2931] chan_iax2.c: USERNAME : em_2 [Jun 12 17:39:52] VERBOSE[2931] chan_iax2.c: REFRESH : 60 [Jun 12 17:39:52] VERBOSE[2931] chan_iax2.c: [Jun 12 17:39:52] VERBOSE[2931] chan_iax2.c: Tx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: CTOKEN [Jun 12 17:39:52] VERBOSE[2931] chan_iax2.c: Timestamp: 00013ms SCall: 00001 DCall: 02293 [10.28.130.121:4569] [Jun 12 17:39:52] VERBOSE[2931] chan_iax2.c: CALLTOKEN : 51 bytes [Jun 12 17:39:52] VERBOSE[2931] chan_iax2.c: [Jun 12 17:39:52] VERBOSE[2932] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: REGREQ [Jun 12 17:39:52] VERBOSE[2932] chan_iax2.c: Timestamp: 00014ms SCall: 02293 DCall: 00000 [10.28.130.121:4569] [Jun 12 17:39:52] VERBOSE[2932] chan_iax2.c: USERNAME : em_2 [Jun 12 17:39:52] VERBOSE[2932] chan_iax2.c: REFRESH : 60 [Jun 12 17:39:52] VERBOSE[2932] chan_iax2.c: CALLTOKEN : 51 bytes [Jun 12 17:39:52] VERBOSE[2932] chan_iax2.c: [Jun 12 17:39:52] DEBUG[2932] chan_iax2.c: ip callno count incremented to 2 for 10.28.130.121 [Jun 12 17:39:52] DEBUG[2932] chan_iax2.c: Creating new call structure 2449 [Jun 12 17:39:52] DEBUG[2932] chan_iax2.c: Received packet 0, (6, 13) [Jun 12 17:39:52] DEBUG[2932] chan_iax2.c: IAX subclass 13 received [Jun 12 17:39:52] DEBUG[2932] chan_iax2.c: For call=2449, set last=14 [Jun 12 17:39:52] DEBUG[2919] devicestate.c: No provider found, checking channel drivers for IAX2 - em_2 [Jun 12 17:39:52] DEBUG[2919] chan_iax2.c: Checking device state for device em_2 [Jun 12 17:39:52] DEBUG[2919] chan_iax2.c: iax2_devicestate: Found peer. What's device state of em_2? addr=169640569, defaddr=0 maxms=0, lastms=0 [Jun 12 17:39:52] DEBUG[2919] devicestate.c: Changing state for IAX2/em_2 - state 0 (Unknown) [Jun 12 17:39:52] DEBUG[2919] devicestate.c: device 'IAX2/em_2' state '0' [Jun 12 17:39:52] DEBUG[2929] chan_iax2.c: Sending 5 on 2449/2293 to 10.28.130.121:4569 [Jun 12 17:39:52] VERBOSE[2929] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: REGAUTH [Jun 12 17:39:52] VERBOSE[2929] chan_iax2.c: Timestamp: 00005ms SCall: 02449 DCall: 02293 [10.28.130.121:4569] [Jun 12 17:39:52] VERBOSE[2929] chan_iax2.c: AUTHMETHODS : 3 [Jun 12 17:39:52] VERBOSE[2929] chan_iax2.c: CHALLENGE : \x34\x30\x37\x34\x33\x30\x39\x38\x34 [Jun 12 17:39:52] VERBOSE[2929] chan_iax2.c: USERNAME : em_2 [Jun 12 17:39:52] VERBOSE[2929] chan_iax2.c: [Jun 12 17:39:52] DEBUG[2954] app_queue.c: Device 'IAX2/em_2' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 12 17:39:52] VERBOSE[2933] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: REGREQ [Jun 12 17:39:52] VERBOSE[2933] chan_iax2.c: Timestamp: 00015ms SCall: 02293 DCall: 02449 [10.28.130.121:4569] [Jun 12 17:39:52] VERBOSE[2933] chan_iax2.c: USERNAME : em_2 [Jun 12 17:39:52] VERBOSE[2933] chan_iax2.c: REFRESH : 60 [Jun 12 17:39:52] VERBOSE[2933] chan_iax2.c: MD5 RESULT : 5909f1535d85b500d27ace828409ee50 [Jun 12 17:39:52] VERBOSE[2933] chan_iax2.c: [Jun 12 17:39:52] DEBUG[2933] chan_iax2.c: Received packet 1, (6, 13) [Jun 12 17:39:52] DEBUG[2933] chan_iax2.c: Cancelling transmission of packet 0 [Jun 12 17:39:52] DEBUG[2933] chan_iax2.c: IAX subclass 13 received [Jun 12 17:39:52] DEBUG[2933] chan_iax2.c: For call=2449, set last=15 [Jun 12 17:39:52] DEBUG[2919] devicestate.c: No provider found, checking channel drivers for IAX2 - em_2 [Jun 12 17:39:52] DEBUG[2919] chan_iax2.c: Checking device state for device em_2 [Jun 12 17:39:52] DEBUG[2919] chan_iax2.c: iax2_devicestate: Found peer. What's device state of em_2? addr=169640569, defaddr=0 maxms=0, lastms=0 [Jun 12 17:39:52] DEBUG[2919] devicestate.c: Changing state for IAX2/em_2 - state 0 (Unknown) [Jun 12 17:39:52] DEBUG[2919] devicestate.c: device 'IAX2/em_2' state '0' [Jun 12 17:39:52] DEBUG[2954] app_queue.c: Device 'IAX2/em_2' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 12 17:39:52] DEBUG[2933] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:39:52] DEBUG[2933] res_config_mysql.c: MySQL RealTime: Update SQL: UPDATE iax_trunk SET `ipaddr` = '10.28.130.121', `port` = '4569', `regseconds` = '1371051592' WHERE `name` = 'em_2' [Jun 12 17:39:52] DEBUG[2933] res_config_mysql.c: MySQL RealTime: Updated 1 rows on table: iax_trunk [Jun 12 17:39:52] DEBUG[2929] chan_iax2.c: Sending 8 on 2449/2293 to 10.28.130.121:4569 [Jun 12 17:39:52] VERBOSE[2929] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: REGACK [Jun 12 17:39:52] VERBOSE[2929] chan_iax2.c: Timestamp: 00008ms SCall: 02449 DCall: 02293 [10.28.130.121:4569] [Jun 12 17:39:52] VERBOSE[2929] chan_iax2.c: USERNAME : em_2 [Jun 12 17:39:52] VERBOSE[2929] chan_iax2.c: DATE TIME : 2013-06-12 17:39:52 [Jun 12 17:39:52] VERBOSE[2929] chan_iax2.c: REFRESH : 60 [Jun 12 17:39:52] VERBOSE[2929] chan_iax2.c: APPARENT ADDRES : IPV4 10.28.130.121:4569 [Jun 12 17:39:52] VERBOSE[2929] chan_iax2.c: [Jun 12 17:39:52] VERBOSE[2934] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK [Jun 12 17:39:52] VERBOSE[2934] chan_iax2.c: Timestamp: 00008ms SCall: 02293 DCall: 02449 [10.28.130.121:4569] [Jun 12 17:39:52] DEBUG[2934] chan_iax2.c: Received packet 2, (6, 4) [Jun 12 17:39:52] DEBUG[2934] chan_iax2.c: Cancelling transmission of packet 1 [Jun 12 17:39:52] DEBUG[2934] chan_iax2.c: Really destroying 2449, having been acked on final message [Jun 12 17:39:52] DEBUG[2934] chan_iax2.c: schedule decrement of callno used for 10.28.130.121 in 60 seconds [Jun 12 17:39:59] DEBUG[2958] chan_sip.c: = Looking for Call ID: KqCXzLqQUjgRo30uuwVP0-BmQ48BBFdd (Checking From) --From tag G3TOuR1kXQzcCkCGq5deV0DouLumCp9C --To-tag [Jun 12 17:39:59] DEBUG[2958] acl.c: For destination '10.28.130.142', our source address is '10.28.130.125'. [Jun 12 17:39:59] DEBUG[2958] chan_sip.c: Setting SIP_TRANSPORT_TCP with address 10.28.130.125:5060 [Jun 12 17:39:59] DEBUG[2958] chan_sip.c: Allocating new SIP dialog for KqCXzLqQUjgRo30uuwVP0-BmQ48BBFdd - REGISTER (No RTP) [Jun 12 17:39:59] DEBUG[2958] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Jun 12 17:39:59] DEBUG[2958] netsock2.c: Splitting '10.28.130.142:52052' into... [Jun 12 17:39:59] DEBUG[2958] netsock2.c: ...host '10.28.130.142' and port '52052'. [Jun 12 17:39:59] DEBUG[2958] netsock2.c: Splitting '10.28.130.125' into... [Jun 12 17:39:59] DEBUG[2958] netsock2.c: ...host '10.28.130.125' and port ''. [Jun 12 17:39:59] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:39:59] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '4200' AND host = 'dynamic' [Jun 12 17:39:59] DEBUG[2958] chan_sip.c: -REALTIME- peer built. Name: 4200. Peer objects: 1 [Jun 12 17:39:59] DEBUG[2958] netsock2.c: Splitting '10.28.130.142' into... [Jun 12 17:39:59] DEBUG[2958] netsock2.c: ...host '10.28.130.142' and port ''. [Jun 12 17:39:59] DEBUG[2958] netsock2.c: Splitting '0.0.0.0' into... [Jun 12 17:39:59] DEBUG[2958] netsock2.c: ...host '0.0.0.0' and port ''. [Jun 12 17:39:59] DEBUG[2958] chan_sip.c: -REALTIME- loading peer from database to memory. Name: 4200. Peer objects: 1 [Jun 12 17:39:59] DEBUG[2958] chan_sip.c: Trying to put 'SIP/2.0 401' onto TCP socket destined for 10.28.130.142:52052 [Jun 12 17:39:59] DEBUG[2958] chan_sip.c: Destroying SIP peer 4200 [Jun 12 17:39:59] DEBUG[2958] chan_sip.c: -REALTIME- peer Destroyed. Name: 4200. Realtime Peer objects: 0 [Jun 12 17:39:59] DEBUG[2958] chan_sip.c: = Looking for Call ID: KqCXzLqQUjgRo30uuwVP0-BmQ48BBFdd (Checking From) --From tag G3TOuR1kXQzcCkCGq5deV0DouLumCp9C --To-tag [Jun 12 17:39:59] DEBUG[2958] netsock2.c: Splitting '10.28.130.125:5060' into... [Jun 12 17:39:59] DEBUG[2958] netsock2.c: ...host '10.28.130.125' and port '5060'. [Jun 12 17:39:59] DEBUG[2958] netsock2.c: Splitting '10.28.130.125:5060' into... [Jun 12 17:39:59] DEBUG[2958] netsock2.c: ...host '10.28.130.125' and port '5060'. [Jun 12 17:39:59] DEBUG[2958] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Jun 12 17:39:59] DEBUG[2958] netsock2.c: Splitting '10.28.130.142:52052' into... [Jun 12 17:39:59] DEBUG[2958] netsock2.c: ...host '10.28.130.142' and port '52052'. [Jun 12 17:39:59] DEBUG[2958] netsock2.c: Splitting '10.28.130.125' into... [Jun 12 17:39:59] DEBUG[2958] netsock2.c: ...host '10.28.130.125' and port ''. [Jun 12 17:39:59] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:39:59] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '4200' AND host = 'dynamic' [Jun 12 17:39:59] DEBUG[2958] chan_sip.c: -REALTIME- peer built. Name: 4200. Peer objects: 1 [Jun 12 17:39:59] DEBUG[2958] netsock2.c: Splitting '10.28.130.142' into... [Jun 12 17:39:59] DEBUG[2958] netsock2.c: ...host '10.28.130.142' and port ''. [Jun 12 17:39:59] DEBUG[2958] netsock2.c: Splitting '0.0.0.0' into... [Jun 12 17:39:59] DEBUG[2958] netsock2.c: ...host '0.0.0.0' and port ''. [Jun 12 17:39:59] DEBUG[2958] chan_sip.c: -REALTIME- loading peer from database to memory. Name: 4200. Peer objects: 1 [Jun 12 17:39:59] DEBUG[2958] chan_sip.c: Store REGISTER's src-IP:port for call routing. [Jun 12 17:39:59] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:39:59] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Update SQL: UPDATE sipexten SET `ipaddr` = '10.28.130.142', `port` = '52052', `regseconds` = '1371051899', `defaultuser` = '4200', `useragent` = 'Digium D40 1_0_5_46476', `lastms` = '0', `fullcontact` = 'sip:4200@10.28.130.142:5060^3Btransport=TCP^3Bob' WHERE `name` = '4200' [Jun 12 17:39:59] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Updated 1 rows on table: sipexten [Jun 12 17:39:59] DEBUG[2958] chan_sip.c: Trying to put 'SIP/2.0 200' onto TCP socket destined for 10.28.130.142:52052 [Jun 12 17:39:59] DEBUG[2919] devicestate.c: No provider found, checking channel drivers for SIP - 4200 [Jun 12 17:39:59] DEBUG[2919] chan_sip.c: Checking device state for peer 4200 [Jun 12 17:39:59] DEBUG[2958] chan_sip.c: Destroying SIP peer 4200 [Jun 12 17:39:59] DEBUG[2958] chan_sip.c: -REALTIME- peer Destroyed. Name: 4200. Realtime Peer objects: 0 [Jun 12 17:39:59] DEBUG[2919] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:39:59] DEBUG[2919] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '4200' AND host = 'dynamic' [Jun 12 17:39:59] DEBUG[2919] chan_sip.c: -REALTIME- peer built. Name: 4200. Peer objects: 1 [Jun 12 17:39:59] DEBUG[2919] netsock2.c: Splitting '10.28.130.142' into... [Jun 12 17:39:59] DEBUG[2919] netsock2.c: ...host '10.28.130.142' and port ''. [Jun 12 17:39:59] DEBUG[2919] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port. [Jun 12 17:39:59] DEBUG[2919] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port. [Jun 12 17:39:59] DEBUG[2919] chan_sip.c: -REALTIME- loading peer from database to memory. Name: 4200. Peer objects: 1 [Jun 12 17:39:59] DEBUG[2919] chan_sip.c: Destroying SIP peer 4200 [Jun 12 17:39:59] DEBUG[2919] chan_sip.c: -REALTIME- peer Destroyed. Name: 4200. Realtime Peer objects: 0 [Jun 12 17:39:59] DEBUG[2919] devicestate.c: Changing state for SIP/4200 - state 1 (Not in use) [Jun 12 17:39:59] DEBUG[2919] devicestate.c: device 'SIP/4200' state '1' [Jun 12 17:39:59] DEBUG[2954] app_queue.c: Device 'SIP/4200' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 12 17:39:59] DEBUG[2958] chan_sip.c: = Looking for Call ID: Px5GZxp59Ip0kxg-SiIph3uChCOCBOq9 (Checking From) --From tag xTpn9jv17ueT9GLjGGp5rpgdtB99siHR --To-tag [Jun 12 17:39:59] DEBUG[2958] acl.c: For destination '10.28.130.142', our source address is '10.28.130.125'. [Jun 12 17:39:59] DEBUG[2958] chan_sip.c: Setting SIP_TRANSPORT_TCP with address 10.28.130.125:5060 [Jun 12 17:39:59] DEBUG[2958] chan_sip.c: Allocating new SIP dialog for Px5GZxp59Ip0kxg-SiIph3uChCOCBOq9 - SUBSCRIBE (No RTP) [Jun 12 17:39:59] DEBUG[2958] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Jun 12 17:39:59] DEBUG[2958] netsock2.c: Splitting '10.28.130.142:52052' into... [Jun 12 17:39:59] DEBUG[2958] netsock2.c: ...host '10.28.130.142' and port '52052'. [Jun 12 17:39:59] DEBUG[2958] chan_sip.c: build_route: Contact hop: "4200" [Jun 12 17:39:59] DEBUG[2958] netsock2.c: Splitting '10.28.130.125' into... [Jun 12 17:39:59] DEBUG[2958] netsock2.c: ...host '10.28.130.125' and port ''. [Jun 12 17:39:59] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:39:59] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '4200' AND host = 'dynamic' [Jun 12 17:39:59] DEBUG[2958] chan_sip.c: -REALTIME- peer built. Name: 4200. Peer objects: 1 [Jun 12 17:39:59] DEBUG[2958] netsock2.c: Splitting '10.28.130.142' into... [Jun 12 17:39:59] DEBUG[2958] netsock2.c: ...host '10.28.130.142' and port ''. [Jun 12 17:39:59] DEBUG[2958] netsock2.c: Splitting '0.0.0.0' into... [Jun 12 17:39:59] DEBUG[2958] netsock2.c: ...host '0.0.0.0' and port ''. [Jun 12 17:39:59] DEBUG[2958] chan_sip.c: -REALTIME- loading peer from database to memory. Name: 4200. Peer objects: 1 [Jun 12 17:39:59] DEBUG[2958] chan_sip.c: Trying to put 'SIP/2.0 401' onto TCP socket destined for 10.28.130.142:52052 [Jun 12 17:39:59] DEBUG[2958] chan_sip.c: Destroying SIP peer 4200 [Jun 12 17:39:59] DEBUG[2958] chan_sip.c: -REALTIME- peer Destroyed. Name: 4200. Realtime Peer objects: 0 [Jun 12 17:39:59] DEBUG[2958] chan_sip.c: = Looking for Call ID: Px5GZxp59Ip0kxg-SiIph3uChCOCBOq9 (Checking From) --From tag xTpn9jv17ueT9GLjGGp5rpgdtB99siHR --To-tag [Jun 12 17:39:59] DEBUG[2958] netsock2.c: Splitting '10.28.130.125:5060' into... [Jun 12 17:39:59] DEBUG[2958] netsock2.c: ...host '10.28.130.125' and port '5060'. [Jun 12 17:39:59] DEBUG[2958] netsock2.c: Splitting '10.28.130.125:5060' into... [Jun 12 17:39:59] DEBUG[2958] netsock2.c: ...host '10.28.130.125' and port '5060'. [Jun 12 17:39:59] DEBUG[2958] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Jun 12 17:39:59] DEBUG[2958] netsock2.c: Splitting '10.28.130.142:52052' into... [Jun 12 17:39:59] DEBUG[2958] netsock2.c: ...host '10.28.130.142' and port '52052'. [Jun 12 17:39:59] DEBUG[2958] chan_sip.c: build_route: Retaining previous route: [Jun 12 17:39:59] DEBUG[2958] netsock2.c: Splitting '10.28.130.125' into... [Jun 12 17:39:59] DEBUG[2958] netsock2.c: ...host '10.28.130.125' and port ''. [Jun 12 17:39:59] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:39:59] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '4200' AND host = 'dynamic' [Jun 12 17:39:59] DEBUG[2958] chan_sip.c: -REALTIME- peer built. Name: 4200. Peer objects: 1 [Jun 12 17:39:59] DEBUG[2958] netsock2.c: Splitting '10.28.130.142' into... [Jun 12 17:39:59] DEBUG[2958] netsock2.c: ...host '10.28.130.142' and port ''. [Jun 12 17:39:59] DEBUG[2958] netsock2.c: Splitting '0.0.0.0' into... [Jun 12 17:39:59] DEBUG[2958] netsock2.c: ...host '0.0.0.0' and port ''. [Jun 12 17:39:59] DEBUG[2958] chan_sip.c: -REALTIME- loading peer from database to memory. Name: 4200. Peer objects: 1 [Jun 12 17:39:59] DEBUG[2958] chan_sip.c: Trying to put 'SIP/2.0 404' onto TCP socket destined for 10.28.130.142:52052 [Jun 12 17:39:59] NOTICE[2958] chan_sip.c: Received SIP subscribe for peer without mailbox: 4200 [Jun 12 17:39:59] DEBUG[2958] chan_sip.c: Destroying SIP peer 4200 [Jun 12 17:39:59] DEBUG[2958] chan_sip.c: -REALTIME- peer Destroyed. Name: 4200. Realtime Peer objects: 0 [Jun 12 17:39:59] DEBUG[2928] chan_sip.c: Destroying SIP dialog Px5GZxp59Ip0kxg-SiIph3uChCOCBOq9 [Jun 12 17:40:02] DEBUG[2930] chan_iax2.c: ip callno count decremented to 1 for 10.28.130.121 [Jun 12 17:40:19] DEBUG[2928] chan_sip.c: = Looking for Call ID: 3168827b0300bc7455c86a247f978468@10.28.130.121 (Checking From) --From tag as1c53a21d --To-tag [Jun 12 17:40:19] DEBUG[2928] acl.c: For destination '10.28.130.121', our source address is '10.28.130.125'. [Jun 12 17:40:19] DEBUG[2928] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.28.130.125:5060 [Jun 12 17:40:19] DEBUG[2928] chan_sip.c: Allocating new SIP dialog for 3168827b0300bc7455c86a247f978468@10.28.130.121 - REGISTER (No RTP) [Jun 12 17:40:19] DEBUG[2928] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Jun 12 17:40:19] DEBUG[2928] netsock2.c: Splitting '10.28.130.121:5060' into... [Jun 12 17:40:19] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port '5060'. [Jun 12 17:40:19] DEBUG[2928] netsock2.c: Splitting '10.28.130.125' into... [Jun 12 17:40:19] DEBUG[2928] netsock2.c: ...host '10.28.130.125' and port ''. [Jun 12 17:40:19] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:40:19] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '4299' AND host = 'dynamic' [Jun 12 17:40:19] DEBUG[2928] chan_sip.c: -REALTIME- peer built. Name: 4299. Peer objects: 1 [Jun 12 17:40:19] DEBUG[2928] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:40:19] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:40:19] DEBUG[2928] netsock2.c: Splitting '0.0.0.0' into... [Jun 12 17:40:19] DEBUG[2928] netsock2.c: ...host '0.0.0.0' and port ''. [Jun 12 17:40:19] DEBUG[2928] chan_sip.c: -REALTIME- loading peer from database to memory. Name: 4299. Peer objects: 1 [Jun 12 17:40:19] DEBUG[2928] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.28.130.121:5060 [Jun 12 17:40:19] DEBUG[2928] chan_sip.c: Destroying SIP peer 4299 [Jun 12 17:40:19] DEBUG[2928] chan_sip.c: -REALTIME- peer Destroyed. Name: 4299. Realtime Peer objects: 0 [Jun 12 17:40:19] DEBUG[2928] chan_sip.c: = Looking for Call ID: 3168827b0300bc7455c86a247f978468@10.28.130.121 (Checking From) --From tag as42893ce6 --To-tag [Jun 12 17:40:19] DEBUG[2928] netsock2.c: Splitting '10.28.130.125' into... [Jun 12 17:40:19] DEBUG[2928] netsock2.c: ...host '10.28.130.125' and port ''. [Jun 12 17:40:19] DEBUG[2928] netsock2.c: Splitting '10.28.130.125' into... [Jun 12 17:40:19] DEBUG[2928] netsock2.c: ...host '10.28.130.125' and port ''. [Jun 12 17:40:19] DEBUG[2928] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Jun 12 17:40:19] DEBUG[2928] netsock2.c: Splitting '10.28.130.121:5060' into... [Jun 12 17:40:19] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port '5060'. [Jun 12 17:40:19] DEBUG[2928] netsock2.c: Splitting '10.28.130.125' into... [Jun 12 17:40:19] DEBUG[2928] netsock2.c: ...host '10.28.130.125' and port ''. [Jun 12 17:40:19] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:40:19] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '4299' AND host = 'dynamic' [Jun 12 17:40:19] DEBUG[2928] chan_sip.c: -REALTIME- peer built. Name: 4299. Peer objects: 1 [Jun 12 17:40:19] DEBUG[2928] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:40:19] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:40:19] DEBUG[2928] netsock2.c: Splitting '0.0.0.0' into... [Jun 12 17:40:19] DEBUG[2928] netsock2.c: ...host '0.0.0.0' and port ''. [Jun 12 17:40:19] DEBUG[2928] chan_sip.c: -REALTIME- loading peer from database to memory. Name: 4299. Peer objects: 1 [Jun 12 17:40:19] DEBUG[2928] chan_sip.c: Store REGISTER's src-IP:port for call routing. [Jun 12 17:40:19] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:40:19] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Update SQL: UPDATE sipexten SET `ipaddr` = '10.28.130.121', `port` = '5060', `regseconds` = '1371051739', `defaultuser` = '4299', `useragent` = 'Asterisk PBX 1.8.14.1', `lastms` = '0', `fullcontact` = 'sip:s@10.28.130.121:5060' WHERE `name` = '4299' [Jun 12 17:40:19] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Updated 1 rows on table: sipexten [Jun 12 17:40:19] DEBUG[2928] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.28.130.121:5060 [Jun 12 17:40:19] DEBUG[2919] devicestate.c: No provider found, checking channel drivers for SIP - 4299 [Jun 12 17:40:19] DEBUG[2919] chan_sip.c: Checking device state for peer 4299 [Jun 12 17:40:19] DEBUG[2928] chan_sip.c: Destroying SIP peer 4299 [Jun 12 17:40:19] DEBUG[2928] chan_sip.c: -REALTIME- peer Destroyed. Name: 4299. Realtime Peer objects: 0 [Jun 12 17:40:19] DEBUG[2919] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:40:19] DEBUG[2919] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '4299' AND host = 'dynamic' [Jun 12 17:40:19] DEBUG[2919] chan_sip.c: -REALTIME- peer built. Name: 4299. Peer objects: 1 [Jun 12 17:40:19] DEBUG[2919] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:40:19] DEBUG[2919] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:40:19] DEBUG[2919] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port. [Jun 12 17:40:19] DEBUG[2919] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port. [Jun 12 17:40:19] DEBUG[2919] chan_sip.c: -REALTIME- loading peer from database to memory. Name: 4299. Peer objects: 1 [Jun 12 17:40:19] DEBUG[2919] chan_sip.c: Destroying SIP peer 4299 [Jun 12 17:40:19] DEBUG[2919] chan_sip.c: -REALTIME- peer Destroyed. Name: 4299. Realtime Peer objects: 0 [Jun 12 17:40:19] DEBUG[2919] devicestate.c: Changing state for SIP/4299 - state 1 (Not in use) [Jun 12 17:40:19] DEBUG[2919] devicestate.c: device 'SIP/4299' state '1' [Jun 12 17:40:19] DEBUG[2954] app_queue.c: Device 'SIP/4299' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 12 17:40:31] DEBUG[2928] chan_sip.c: Auto destroying SIP dialog 'KqCXzLqQUjgRo30uuwVP0-BmQ48BBFdd' [Jun 12 17:40:31] DEBUG[2928] chan_sip.c: Destroying SIP dialog KqCXzLqQUjgRo30uuwVP0-BmQ48BBFdd [Jun 12 17:40:42] VERBOSE[2937] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: REGREQ [Jun 12 17:40:42] VERBOSE[2937] chan_iax2.c: Timestamp: 00003ms SCall: 03537 DCall: 00000 [10.28.130.121:4569] [Jun 12 17:40:42] VERBOSE[2937] chan_iax2.c: USERNAME : em_2 [Jun 12 17:40:42] VERBOSE[2937] chan_iax2.c: REFRESH : 60 [Jun 12 17:40:42] VERBOSE[2937] chan_iax2.c: [Jun 12 17:40:42] VERBOSE[2937] chan_iax2.c: Tx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: CTOKEN [Jun 12 17:40:42] VERBOSE[2937] chan_iax2.c: Timestamp: 00003ms SCall: 00001 DCall: 03537 [10.28.130.121:4569] [Jun 12 17:40:42] VERBOSE[2937] chan_iax2.c: CALLTOKEN : 51 bytes [Jun 12 17:40:42] VERBOSE[2937] chan_iax2.c: [Jun 12 17:40:42] VERBOSE[2938] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: REGREQ [Jun 12 17:40:42] VERBOSE[2938] chan_iax2.c: Timestamp: 00006ms SCall: 03537 DCall: 00000 [10.28.130.121:4569] [Jun 12 17:40:42] VERBOSE[2938] chan_iax2.c: USERNAME : em_2 [Jun 12 17:40:42] VERBOSE[2938] chan_iax2.c: REFRESH : 60 [Jun 12 17:40:42] VERBOSE[2938] chan_iax2.c: CALLTOKEN : 51 bytes [Jun 12 17:40:42] VERBOSE[2938] chan_iax2.c: [Jun 12 17:40:42] DEBUG[2938] chan_iax2.c: ip callno count incremented to 2 for 10.28.130.121 [Jun 12 17:40:42] DEBUG[2938] chan_iax2.c: Creating new call structure 1692 [Jun 12 17:40:42] DEBUG[2938] chan_iax2.c: Received packet 0, (6, 13) [Jun 12 17:40:42] DEBUG[2938] chan_iax2.c: IAX subclass 13 received [Jun 12 17:40:42] DEBUG[2938] chan_iax2.c: For call=1692, set last=6 [Jun 12 17:40:42] DEBUG[2919] devicestate.c: No provider found, checking channel drivers for IAX2 - em_2 [Jun 12 17:40:42] DEBUG[2919] chan_iax2.c: Checking device state for device em_2 [Jun 12 17:40:42] DEBUG[2919] chan_iax2.c: iax2_devicestate: Found peer. What's device state of em_2? addr=169640569, defaddr=0 maxms=0, lastms=0 [Jun 12 17:40:42] DEBUG[2919] devicestate.c: Changing state for IAX2/em_2 - state 0 (Unknown) [Jun 12 17:40:42] DEBUG[2919] devicestate.c: device 'IAX2/em_2' state '0' [Jun 12 17:40:42] DEBUG[2929] chan_iax2.c: Sending 9 on 1692/3537 to 10.28.130.121:4569 [Jun 12 17:40:42] VERBOSE[2929] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: REGAUTH [Jun 12 17:40:42] VERBOSE[2929] chan_iax2.c: Timestamp: 00009ms SCall: 01692 DCall: 03537 [10.28.130.121:4569] [Jun 12 17:40:42] VERBOSE[2929] chan_iax2.c: AUTHMETHODS : 3 [Jun 12 17:40:42] VERBOSE[2929] chan_iax2.c: CHALLENGE : \x32\x30\x36\x35\x31\x31\x33\x38\x34 [Jun 12 17:40:42] VERBOSE[2929] chan_iax2.c: USERNAME : em_2 [Jun 12 17:40:42] VERBOSE[2929] chan_iax2.c: [Jun 12 17:40:42] DEBUG[2954] app_queue.c: Device 'IAX2/em_2' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 12 17:40:42] VERBOSE[2939] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: REGREQ [Jun 12 17:40:42] VERBOSE[2939] chan_iax2.c: Timestamp: 00009ms SCall: 03537 DCall: 01692 [10.28.130.121:4569] [Jun 12 17:40:42] VERBOSE[2939] chan_iax2.c: USERNAME : em_2 [Jun 12 17:40:42] VERBOSE[2939] chan_iax2.c: REFRESH : 60 [Jun 12 17:40:42] VERBOSE[2939] chan_iax2.c: MD5 RESULT : df37b7082322740b2dafebb060e82d7c [Jun 12 17:40:42] VERBOSE[2939] chan_iax2.c: [Jun 12 17:40:42] DEBUG[2939] chan_iax2.c: Received packet 1, (6, 13) [Jun 12 17:40:42] DEBUG[2939] chan_iax2.c: Cancelling transmission of packet 0 [Jun 12 17:40:42] DEBUG[2939] chan_iax2.c: IAX subclass 13 received [Jun 12 17:40:42] DEBUG[2939] chan_iax2.c: For call=1692, set last=9 [Jun 12 17:40:42] DEBUG[2919] devicestate.c: No provider found, checking channel drivers for IAX2 - em_2 [Jun 12 17:40:42] DEBUG[2919] chan_iax2.c: Checking device state for device em_2 [Jun 12 17:40:42] DEBUG[2919] chan_iax2.c: iax2_devicestate: Found peer. What's device state of em_2? addr=169640569, defaddr=0 maxms=0, lastms=0 [Jun 12 17:40:42] DEBUG[2919] devicestate.c: Changing state for IAX2/em_2 - state 0 (Unknown) [Jun 12 17:40:42] DEBUG[2919] devicestate.c: device 'IAX2/em_2' state '0' [Jun 12 17:40:42] DEBUG[2954] app_queue.c: Device 'IAX2/em_2' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 12 17:40:42] DEBUG[2939] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:40:42] DEBUG[2939] res_config_mysql.c: MySQL RealTime: Update SQL: UPDATE iax_trunk SET `ipaddr` = '10.28.130.121', `port` = '4569', `regseconds` = '1371051642' WHERE `name` = 'em_2' [Jun 12 17:40:42] DEBUG[2939] res_config_mysql.c: MySQL RealTime: Updated 1 rows on table: iax_trunk [Jun 12 17:40:42] DEBUG[2929] chan_iax2.c: Sending 12 on 1692/3537 to 10.28.130.121:4569 [Jun 12 17:40:42] VERBOSE[2929] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: REGACK [Jun 12 17:40:42] VERBOSE[2929] chan_iax2.c: Timestamp: 00012ms SCall: 01692 DCall: 03537 [10.28.130.121:4569] [Jun 12 17:40:42] VERBOSE[2929] chan_iax2.c: USERNAME : em_2 [Jun 12 17:40:42] VERBOSE[2929] chan_iax2.c: DATE TIME : 2013-06-12 17:40:42 [Jun 12 17:40:42] VERBOSE[2929] chan_iax2.c: REFRESH : 60 [Jun 12 17:40:42] VERBOSE[2929] chan_iax2.c: APPARENT ADDRES : IPV4 10.28.130.121:4569 [Jun 12 17:40:42] VERBOSE[2929] chan_iax2.c: [Jun 12 17:40:42] VERBOSE[2940] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK [Jun 12 17:40:42] VERBOSE[2940] chan_iax2.c: Timestamp: 00012ms SCall: 03537 DCall: 01692 [10.28.130.121:4569] [Jun 12 17:40:42] DEBUG[2940] chan_iax2.c: Received packet 2, (6, 4) [Jun 12 17:40:42] DEBUG[2940] chan_iax2.c: Cancelling transmission of packet 1 [Jun 12 17:40:42] DEBUG[2940] chan_iax2.c: Really destroying 1692, having been acked on final message [Jun 12 17:40:42] DEBUG[2940] chan_iax2.c: schedule decrement of callno used for 10.28.130.121 in 60 seconds [Jun 12 17:40:51] DEBUG[2928] chan_sip.c: Auto destroying SIP dialog '3168827b0300bc7455c86a247f978468@10.28.130.121' [Jun 12 17:40:51] DEBUG[2928] chan_sip.c: Destroying SIP dialog 3168827b0300bc7455c86a247f978468@10.28.130.121 [Jun 12 17:40:52] DEBUG[2930] chan_iax2.c: ip callno count decremented to 1 for 10.28.130.121 [Jun 12 17:40:59] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:40:59] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '10.28.130.121' AND host = 'dynamic' [Jun 12 17:40:59] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:40:59] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '10.28.130.121' [Jun 12 17:40:59] DEBUG[2928] chan_sip.c: SIP Registry 10.28.130.121: refcount now 3 [Jun 12 17:40:59] DEBUG[2928] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:40:59] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:40:59] DEBUG[2928] chan_sip.c: SIP Registry 10.28.130.121: refcount now 2 [Jun 12 17:40:59] DEBUG[2928] chan_sip.c: Allocating new SIP dialog for 0df587045630ad970a2a21583d853f9f@10.28.130.125 - REGISTER (No RTP) [Jun 12 17:40:59] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:40:59] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '10.28.130.121' AND host = 'dynamic' [Jun 12 17:40:59] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:40:59] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '10.28.130.121' [Jun 12 17:40:59] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:40:59] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '10.28.130.121' AND host = 'dynamic' [Jun 12 17:40:59] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:40:59] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '10.28.130.121' [Jun 12 17:40:59] DEBUG[2928] chan_sip.c: SIP Registry 10.28.130.121: refcount now 3 [Jun 12 17:40:59] DEBUG[2928] acl.c: For destination '10.28.130.121', our source address is '10.28.130.125'. [Jun 12 17:40:59] DEBUG[2928] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.28.130.125:5060 [Jun 12 17:40:59] DEBUG[2928] chan_sip.c: SIP Registry 10.28.130.121: refcount now 4 [Jun 12 17:40:59] DEBUG[2928] chan_sip.c: Scheduled a registration timeout for 10.28.130.121 id #48831 [Jun 12 17:40:59] DEBUG[2928] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:40:59] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:40:59] DEBUG[2928] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:40:59] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:40:59] DEBUG[2928] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:40:59] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:40:59] DEBUG[2928] chan_sip.c: Initializing initreq for method REGISTER - callid 0df587045630ad970a2a21583d853f9f@10.28.130.125 [Jun 12 17:40:59] DEBUG[2928] chan_sip.c: REGISTER attempt 1 to 2997@10.28.130.121 [Jun 12 17:40:59] DEBUG[2928] chan_sip.c: Trying to put 'REGISTER si' onto UDP socket destined for 10.28.130.121:5060 [Jun 12 17:40:59] DEBUG[2928] chan_sip.c: SIP Registry 10.28.130.121: refcount now 3 [Jun 12 17:40:59] DEBUG[2928] chan_sip.c: = Looking for Call ID: 0df587045630ad970a2a21583d853f9f@10.28.130.125 (Checking To) --From tag as203c84b7 --To-tag as3234e9e5 [Jun 12 17:40:59] DEBUG[2928] chan_sip.c: Stopping retransmission on '0df587045630ad970a2a21583d853f9f@10.28.130.125' of Request 10016: Match Found [Jun 12 17:40:59] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:40:59] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '10.28.130.121' AND host = 'dynamic' [Jun 12 17:40:59] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:40:59] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '10.28.130.121' [Jun 12 17:40:59] DEBUG[2928] chan_sip.c: SIP Registry 10.28.130.121: refcount now 4 [Jun 12 17:40:59] DEBUG[2928] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:40:59] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:40:59] DEBUG[2928] chan_sip.c: SIP Registry 10.28.130.121: refcount now 3 [Jun 12 17:40:59] DEBUG[2928] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:40:59] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:40:59] DEBUG[2928] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:40:59] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:40:59] DEBUG[2928] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:40:59] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:40:59] DEBUG[2928] chan_sip.c: Initializing already initialized SIP dialog 0df587045630ad970a2a21583d853f9f@10.28.130.125 (presumably reinvite) [Jun 12 17:40:59] DEBUG[2928] chan_sip.c: REGISTER attempt 2 to 2997@10.28.130.121 [Jun 12 17:40:59] DEBUG[2928] chan_sip.c: Trying to put 'REGISTER si' onto UDP socket destined for 10.28.130.121:5060 [Jun 12 17:40:59] DEBUG[2928] chan_sip.c: = Looking for Call ID: 0df587045630ad970a2a21583d853f9f@10.28.130.125 (Checking To) --From tag as1c6d550d --To-tag as3234e9e5 [Jun 12 17:40:59] DEBUG[2928] chan_sip.c: Stopping retransmission on '0df587045630ad970a2a21583d853f9f@10.28.130.125' of Request 10017: Match Found [Jun 12 17:40:59] DEBUG[2928] chan_sip.c: Registration successful [Jun 12 17:40:59] DEBUG[2928] chan_sip.c: Cancelling timeout 48831 [Jun 12 17:40:59] DEBUG[2928] chan_sip.c: SIP Registry 10.28.130.121: refcount now 2 [Jun 12 17:40:59] DEBUG[2928] chan_sip.c: SIP Registry 10.28.130.121: refcount now 1 [Jun 12 17:40:59] DEBUG[2928] chan_sip.c: SIP Registry 10.28.130.121: refcount now 2 [Jun 12 17:41:31] DEBUG[2928] chan_sip.c: Auto destroying SIP dialog '0df587045630ad970a2a21583d853f9f@10.28.130.125' [Jun 12 17:41:31] DEBUG[2928] chan_sip.c: Destroying SIP dialog 0df587045630ad970a2a21583d853f9f@10.28.130.125 [Jun 12 17:41:32] VERBOSE[2933] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: REGREQ [Jun 12 17:41:32] VERBOSE[2933] chan_iax2.c: Timestamp: 00005ms SCall: 08860 DCall: 00000 [10.28.130.121:4569] [Jun 12 17:41:32] VERBOSE[2933] chan_iax2.c: USERNAME : em_2 [Jun 12 17:41:32] VERBOSE[2933] chan_iax2.c: REFRESH : 60 [Jun 12 17:41:32] VERBOSE[2933] chan_iax2.c: [Jun 12 17:41:32] VERBOSE[2933] chan_iax2.c: Tx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: CTOKEN [Jun 12 17:41:32] VERBOSE[2933] chan_iax2.c: Timestamp: 00005ms SCall: 00001 DCall: 08860 [10.28.130.121:4569] [Jun 12 17:41:32] VERBOSE[2933] chan_iax2.c: CALLTOKEN : 51 bytes [Jun 12 17:41:32] VERBOSE[2933] chan_iax2.c: [Jun 12 17:41:32] VERBOSE[2934] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: REGREQ [Jun 12 17:41:32] VERBOSE[2934] chan_iax2.c: Timestamp: 00009ms SCall: 08860 DCall: 00000 [10.28.130.121:4569] [Jun 12 17:41:32] VERBOSE[2934] chan_iax2.c: USERNAME : em_2 [Jun 12 17:41:32] VERBOSE[2934] chan_iax2.c: REFRESH : 60 [Jun 12 17:41:32] VERBOSE[2934] chan_iax2.c: CALLTOKEN : 51 bytes [Jun 12 17:41:32] VERBOSE[2934] chan_iax2.c: [Jun 12 17:41:32] DEBUG[2934] chan_iax2.c: ip callno count incremented to 2 for 10.28.130.121 [Jun 12 17:41:32] DEBUG[2934] chan_iax2.c: Creating new call structure 2522 [Jun 12 17:41:32] DEBUG[2934] chan_iax2.c: Received packet 0, (6, 13) [Jun 12 17:41:32] DEBUG[2934] chan_iax2.c: IAX subclass 13 received [Jun 12 17:41:32] DEBUG[2934] chan_iax2.c: For call=2522, set last=9 [Jun 12 17:41:32] DEBUG[2919] devicestate.c: No provider found, checking channel drivers for IAX2 - em_2 [Jun 12 17:41:32] DEBUG[2919] chan_iax2.c: Checking device state for device em_2 [Jun 12 17:41:32] DEBUG[2919] chan_iax2.c: iax2_devicestate: Found peer. What's device state of em_2? addr=169640569, defaddr=0 maxms=0, lastms=0 [Jun 12 17:41:32] DEBUG[2919] devicestate.c: Changing state for IAX2/em_2 - state 0 (Unknown) [Jun 12 17:41:32] DEBUG[2919] devicestate.c: device 'IAX2/em_2' state '0' [Jun 12 17:41:32] DEBUG[2929] chan_iax2.c: Sending 16 on 2522/8860 to 10.28.130.121:4569 [Jun 12 17:41:32] VERBOSE[2929] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: REGAUTH [Jun 12 17:41:32] VERBOSE[2929] chan_iax2.c: Timestamp: 00016ms SCall: 02522 DCall: 08860 [10.28.130.121:4569] [Jun 12 17:41:32] VERBOSE[2929] chan_iax2.c: AUTHMETHODS : 3 [Jun 12 17:41:32] VERBOSE[2929] chan_iax2.c: CHALLENGE : \x38\x36\x36\x39\x33\x36\x31\x37\x34 [Jun 12 17:41:32] VERBOSE[2929] chan_iax2.c: USERNAME : em_2 [Jun 12 17:41:32] VERBOSE[2929] chan_iax2.c: [Jun 12 17:41:32] DEBUG[2954] app_queue.c: Device 'IAX2/em_2' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 12 17:41:32] VERBOSE[2935] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: REGREQ [Jun 12 17:41:32] VERBOSE[2935] chan_iax2.c: Timestamp: 00010ms SCall: 08860 DCall: 02522 [10.28.130.121:4569] [Jun 12 17:41:32] VERBOSE[2935] chan_iax2.c: USERNAME : em_2 [Jun 12 17:41:32] VERBOSE[2935] chan_iax2.c: REFRESH : 60 [Jun 12 17:41:32] VERBOSE[2935] chan_iax2.c: MD5 RESULT : eb9745bd7b125ba511ed4476079bd10e [Jun 12 17:41:32] VERBOSE[2935] chan_iax2.c: [Jun 12 17:41:32] DEBUG[2935] chan_iax2.c: Received packet 1, (6, 13) [Jun 12 17:41:32] DEBUG[2935] chan_iax2.c: Cancelling transmission of packet 0 [Jun 12 17:41:32] DEBUG[2935] chan_iax2.c: IAX subclass 13 received [Jun 12 17:41:32] DEBUG[2935] chan_iax2.c: For call=2522, set last=10 [Jun 12 17:41:32] DEBUG[2919] devicestate.c: No provider found, checking channel drivers for IAX2 - em_2 [Jun 12 17:41:32] DEBUG[2919] chan_iax2.c: Checking device state for device em_2 [Jun 12 17:41:32] DEBUG[2919] chan_iax2.c: iax2_devicestate: Found peer. What's device state of em_2? addr=169640569, defaddr=0 maxms=0, lastms=0 [Jun 12 17:41:32] DEBUG[2919] devicestate.c: Changing state for IAX2/em_2 - state 0 (Unknown) [Jun 12 17:41:32] DEBUG[2919] devicestate.c: device 'IAX2/em_2' state '0' [Jun 12 17:41:32] DEBUG[2954] app_queue.c: Device 'IAX2/em_2' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 12 17:41:32] DEBUG[2935] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:41:32] DEBUG[2935] res_config_mysql.c: MySQL RealTime: Update SQL: UPDATE iax_trunk SET `ipaddr` = '10.28.130.121', `port` = '4569', `regseconds` = '1371051692' WHERE `name` = 'em_2' [Jun 12 17:41:32] DEBUG[2935] res_config_mysql.c: MySQL RealTime: Updated 1 rows on table: iax_trunk [Jun 12 17:41:32] DEBUG[2929] chan_iax2.c: Sending 19 on 2522/8860 to 10.28.130.121:4569 [Jun 12 17:41:32] VERBOSE[2929] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: REGACK [Jun 12 17:41:32] VERBOSE[2929] chan_iax2.c: Timestamp: 00019ms SCall: 02522 DCall: 08860 [10.28.130.121:4569] [Jun 12 17:41:32] VERBOSE[2929] chan_iax2.c: USERNAME : em_2 [Jun 12 17:41:32] VERBOSE[2929] chan_iax2.c: DATE TIME : 2013-06-12 17:41:32 [Jun 12 17:41:32] VERBOSE[2929] chan_iax2.c: REFRESH : 60 [Jun 12 17:41:32] VERBOSE[2929] chan_iax2.c: APPARENT ADDRES : IPV4 10.28.130.121:4569 [Jun 12 17:41:32] VERBOSE[2929] chan_iax2.c: [Jun 12 17:41:32] VERBOSE[2936] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK [Jun 12 17:41:32] VERBOSE[2936] chan_iax2.c: Timestamp: 00019ms SCall: 08860 DCall: 02522 [10.28.130.121:4569] [Jun 12 17:41:32] DEBUG[2936] chan_iax2.c: Received packet 2, (6, 4) [Jun 12 17:41:32] DEBUG[2936] chan_iax2.c: Cancelling transmission of packet 1 [Jun 12 17:41:32] DEBUG[2936] chan_iax2.c: Really destroying 2522, having been acked on final message [Jun 12 17:41:32] DEBUG[2936] chan_iax2.c: schedule decrement of callno used for 10.28.130.121 in 60 seconds [Jun 12 17:41:42] DEBUG[2930] chan_iax2.c: ip callno count decremented to 1 for 10.28.130.121 [Jun 12 17:42:04] DEBUG[2928] chan_sip.c: = Looking for Call ID: 3168827b0300bc7455c86a247f978468@10.28.130.121 (Checking From) --From tag as0fbc2694 --To-tag [Jun 12 17:42:04] DEBUG[2928] acl.c: For destination '10.28.130.121', our source address is '10.28.130.125'. [Jun 12 17:42:04] DEBUG[2928] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.28.130.125:5060 [Jun 12 17:42:04] DEBUG[2928] chan_sip.c: Allocating new SIP dialog for 3168827b0300bc7455c86a247f978468@10.28.130.121 - REGISTER (No RTP) [Jun 12 17:42:04] DEBUG[2928] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Jun 12 17:42:04] DEBUG[2928] netsock2.c: Splitting '10.28.130.121:5060' into... [Jun 12 17:42:04] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port '5060'. [Jun 12 17:42:04] DEBUG[2928] netsock2.c: Splitting '10.28.130.125' into... [Jun 12 17:42:04] DEBUG[2928] netsock2.c: ...host '10.28.130.125' and port ''. [Jun 12 17:42:04] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:42:04] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '4299' AND host = 'dynamic' [Jun 12 17:42:04] DEBUG[2928] chan_sip.c: -REALTIME- peer built. Name: 4299. Peer objects: 1 [Jun 12 17:42:04] DEBUG[2928] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:42:04] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:42:04] DEBUG[2928] netsock2.c: Splitting '0.0.0.0' into... [Jun 12 17:42:04] DEBUG[2928] netsock2.c: ...host '0.0.0.0' and port ''. [Jun 12 17:42:04] DEBUG[2928] chan_sip.c: -REALTIME- loading peer from database to memory. Name: 4299. Peer objects: 1 [Jun 12 17:42:04] DEBUG[2928] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for 10.28.130.121:5060 [Jun 12 17:42:04] DEBUG[2928] chan_sip.c: Destroying SIP peer 4299 [Jun 12 17:42:04] DEBUG[2928] chan_sip.c: -REALTIME- peer Destroyed. Name: 4299. Realtime Peer objects: 0 [Jun 12 17:42:04] DEBUG[2928] chan_sip.c: = Looking for Call ID: 3168827b0300bc7455c86a247f978468@10.28.130.121 (Checking From) --From tag as252a7b86 --To-tag [Jun 12 17:42:04] DEBUG[2928] netsock2.c: Splitting '10.28.130.125' into... [Jun 12 17:42:04] DEBUG[2928] netsock2.c: ...host '10.28.130.125' and port ''. [Jun 12 17:42:04] DEBUG[2928] netsock2.c: Splitting '10.28.130.125' into... [Jun 12 17:42:04] DEBUG[2928] netsock2.c: ...host '10.28.130.125' and port ''. [Jun 12 17:42:04] DEBUG[2928] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Jun 12 17:42:04] DEBUG[2928] netsock2.c: Splitting '10.28.130.121:5060' into... [Jun 12 17:42:04] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port '5060'. [Jun 12 17:42:04] DEBUG[2928] netsock2.c: Splitting '10.28.130.125' into... [Jun 12 17:42:04] DEBUG[2928] netsock2.c: ...host '10.28.130.125' and port ''. [Jun 12 17:42:04] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:42:04] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '4299' AND host = 'dynamic' [Jun 12 17:42:04] DEBUG[2928] chan_sip.c: -REALTIME- peer built. Name: 4299. Peer objects: 1 [Jun 12 17:42:04] DEBUG[2928] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:42:04] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:42:04] DEBUG[2928] netsock2.c: Splitting '0.0.0.0' into... [Jun 12 17:42:04] DEBUG[2928] netsock2.c: ...host '0.0.0.0' and port ''. [Jun 12 17:42:04] DEBUG[2928] chan_sip.c: -REALTIME- loading peer from database to memory. Name: 4299. Peer objects: 1 [Jun 12 17:42:04] DEBUG[2928] chan_sip.c: Store REGISTER's src-IP:port for call routing. [Jun 12 17:42:04] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:42:04] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Update SQL: UPDATE sipexten SET `ipaddr` = '10.28.130.121', `port` = '5060', `regseconds` = '1371051844', `defaultuser` = '4299', `useragent` = 'Asterisk PBX 1.8.14.1', `lastms` = '0', `fullcontact` = 'sip:s@10.28.130.121:5060' WHERE `name` = '4299' [Jun 12 17:42:04] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Updated 1 rows on table: sipexten [Jun 12 17:42:04] DEBUG[2928] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 10.28.130.121:5060 [Jun 12 17:42:04] DEBUG[2919] devicestate.c: No provider found, checking channel drivers for SIP - 4299 [Jun 12 17:42:04] DEBUG[2919] chan_sip.c: Checking device state for peer 4299 [Jun 12 17:42:04] DEBUG[2928] chan_sip.c: Destroying SIP peer 4299 [Jun 12 17:42:04] DEBUG[2928] chan_sip.c: -REALTIME- peer Destroyed. Name: 4299. Realtime Peer objects: 0 [Jun 12 17:42:04] DEBUG[2919] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:42:04] DEBUG[2919] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '4299' AND host = 'dynamic' [Jun 12 17:42:04] DEBUG[2919] chan_sip.c: -REALTIME- peer built. Name: 4299. Peer objects: 1 [Jun 12 17:42:04] DEBUG[2919] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:42:04] DEBUG[2919] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:42:04] DEBUG[2919] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port. [Jun 12 17:42:04] DEBUG[2919] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port. [Jun 12 17:42:04] DEBUG[2919] chan_sip.c: -REALTIME- loading peer from database to memory. Name: 4299. Peer objects: 1 [Jun 12 17:42:04] DEBUG[2919] chan_sip.c: Destroying SIP peer 4299 [Jun 12 17:42:04] DEBUG[2919] chan_sip.c: -REALTIME- peer Destroyed. Name: 4299. Realtime Peer objects: 0 [Jun 12 17:42:04] DEBUG[2919] devicestate.c: Changing state for SIP/4299 - state 1 (Not in use) [Jun 12 17:42:04] DEBUG[2919] devicestate.c: device 'SIP/4299' state '1' [Jun 12 17:42:04] DEBUG[2954] app_queue.c: Device 'SIP/4299' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 12 17:42:22] VERBOSE[2939] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: REGREQ [Jun 12 17:42:22] VERBOSE[2939] chan_iax2.c: Timestamp: 00015ms SCall: 00562 DCall: 00000 [10.28.130.121:4569] [Jun 12 17:42:22] VERBOSE[2939] chan_iax2.c: USERNAME : em_2 [Jun 12 17:42:22] VERBOSE[2939] chan_iax2.c: REFRESH : 60 [Jun 12 17:42:22] VERBOSE[2939] chan_iax2.c: [Jun 12 17:42:22] VERBOSE[2939] chan_iax2.c: Tx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: CTOKEN [Jun 12 17:42:22] VERBOSE[2939] chan_iax2.c: Timestamp: 00015ms SCall: 00001 DCall: 00562 [10.28.130.121:4569] [Jun 12 17:42:22] VERBOSE[2939] chan_iax2.c: CALLTOKEN : 51 bytes [Jun 12 17:42:22] VERBOSE[2939] chan_iax2.c: [Jun 12 17:42:22] VERBOSE[2940] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 000 ISeqno: 000 Type: IAX Subclass: REGREQ [Jun 12 17:42:22] VERBOSE[2940] chan_iax2.c: Timestamp: 00018ms SCall: 00562 DCall: 00000 [10.28.130.121:4569] [Jun 12 17:42:22] VERBOSE[2940] chan_iax2.c: USERNAME : em_2 [Jun 12 17:42:22] VERBOSE[2940] chan_iax2.c: REFRESH : 60 [Jun 12 17:42:22] VERBOSE[2940] chan_iax2.c: CALLTOKEN : 51 bytes [Jun 12 17:42:22] VERBOSE[2940] chan_iax2.c: [Jun 12 17:42:22] DEBUG[2940] chan_iax2.c: ip callno count incremented to 2 for 10.28.130.121 [Jun 12 17:42:22] DEBUG[2940] chan_iax2.c: Creating new call structure 1701 [Jun 12 17:42:22] DEBUG[2940] chan_iax2.c: Received packet 0, (6, 13) [Jun 12 17:42:22] DEBUG[2940] chan_iax2.c: IAX subclass 13 received [Jun 12 17:42:22] DEBUG[2940] chan_iax2.c: For call=1701, set last=18 [Jun 12 17:42:22] DEBUG[2919] devicestate.c: No provider found, checking channel drivers for IAX2 - em_2 [Jun 12 17:42:22] DEBUG[2919] chan_iax2.c: Checking device state for device em_2 [Jun 12 17:42:22] DEBUG[2919] chan_iax2.c: iax2_devicestate: Found peer. What's device state of em_2? addr=169640569, defaddr=0 maxms=0, lastms=0 [Jun 12 17:42:22] DEBUG[2919] devicestate.c: Changing state for IAX2/em_2 - state 0 (Unknown) [Jun 12 17:42:22] DEBUG[2919] devicestate.c: device 'IAX2/em_2' state '0' [Jun 12 17:42:22] DEBUG[2929] chan_iax2.c: Sending 3 on 1701/562 to 10.28.130.121:4569 [Jun 12 17:42:22] VERBOSE[2929] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 000 ISeqno: 001 Type: IAX Subclass: REGAUTH [Jun 12 17:42:22] VERBOSE[2929] chan_iax2.c: Timestamp: 00003ms SCall: 01701 DCall: 00562 [10.28.130.121:4569] [Jun 12 17:42:22] VERBOSE[2929] chan_iax2.c: AUTHMETHODS : 3 [Jun 12 17:42:22] VERBOSE[2929] chan_iax2.c: CHALLENGE : \x33\x32\x31\x35\x36\x35\x38\x34\x32 [Jun 12 17:42:22] VERBOSE[2929] chan_iax2.c: USERNAME : em_2 [Jun 12 17:42:22] VERBOSE[2929] chan_iax2.c: [Jun 12 17:42:22] DEBUG[2954] app_queue.c: Device 'IAX2/em_2' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 12 17:42:22] VERBOSE[2931] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 001 ISeqno: 001 Type: IAX Subclass: REGREQ [Jun 12 17:42:22] VERBOSE[2931] chan_iax2.c: Timestamp: 00021ms SCall: 00562 DCall: 01701 [10.28.130.121:4569] [Jun 12 17:42:22] VERBOSE[2931] chan_iax2.c: USERNAME : em_2 [Jun 12 17:42:22] VERBOSE[2931] chan_iax2.c: REFRESH : 60 [Jun 12 17:42:22] VERBOSE[2931] chan_iax2.c: MD5 RESULT : e145cd05207d8612c726b696a3785389 [Jun 12 17:42:22] VERBOSE[2931] chan_iax2.c: [Jun 12 17:42:22] DEBUG[2931] chan_iax2.c: Received packet 1, (6, 13) [Jun 12 17:42:22] DEBUG[2931] chan_iax2.c: Cancelling transmission of packet 0 [Jun 12 17:42:22] DEBUG[2931] chan_iax2.c: IAX subclass 13 received [Jun 12 17:42:22] DEBUG[2931] chan_iax2.c: For call=1701, set last=21 [Jun 12 17:42:22] DEBUG[2919] devicestate.c: No provider found, checking channel drivers for IAX2 - em_2 [Jun 12 17:42:22] DEBUG[2919] chan_iax2.c: Checking device state for device em_2 [Jun 12 17:42:22] DEBUG[2919] chan_iax2.c: iax2_devicestate: Found peer. What's device state of em_2? addr=169640569, defaddr=0 maxms=0, lastms=0 [Jun 12 17:42:22] DEBUG[2919] devicestate.c: Changing state for IAX2/em_2 - state 0 (Unknown) [Jun 12 17:42:22] DEBUG[2919] devicestate.c: device 'IAX2/em_2' state '0' [Jun 12 17:42:22] DEBUG[2954] app_queue.c: Device 'IAX2/em_2' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Jun 12 17:42:22] DEBUG[2931] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:42:22] DEBUG[2931] res_config_mysql.c: MySQL RealTime: Update SQL: UPDATE iax_trunk SET `ipaddr` = '10.28.130.121', `port` = '4569', `regseconds` = '1371051742' WHERE `name` = 'em_2' [Jun 12 17:42:22] DEBUG[2931] res_config_mysql.c: MySQL RealTime: Updated 1 rows on table: iax_trunk [Jun 12 17:42:22] DEBUG[2929] chan_iax2.c: Sending 6 on 1701/562 to 10.28.130.121:4569 [Jun 12 17:42:22] VERBOSE[2929] chan_iax2.c: Tx-Frame Retry[000] -- OSeqno: 001 ISeqno: 002 Type: IAX Subclass: REGACK [Jun 12 17:42:22] VERBOSE[2929] chan_iax2.c: Timestamp: 00006ms SCall: 01701 DCall: 00562 [10.28.130.121:4569] [Jun 12 17:42:22] VERBOSE[2929] chan_iax2.c: USERNAME : em_2 [Jun 12 17:42:22] VERBOSE[2929] chan_iax2.c: DATE TIME : 2013-06-12 17:42:22 [Jun 12 17:42:22] VERBOSE[2929] chan_iax2.c: REFRESH : 60 [Jun 12 17:42:22] VERBOSE[2929] chan_iax2.c: APPARENT ADDRES : IPV4 10.28.130.121:4569 [Jun 12 17:42:22] VERBOSE[2929] chan_iax2.c: [Jun 12 17:42:22] VERBOSE[2932] chan_iax2.c: Rx-Frame Retry[ No] -- OSeqno: 002 ISeqno: 002 Type: IAX Subclass: ACK [Jun 12 17:42:22] VERBOSE[2932] chan_iax2.c: Timestamp: 00006ms SCall: 00562 DCall: 01701 [10.28.130.121:4569] [Jun 12 17:42:22] DEBUG[2932] chan_iax2.c: Received packet 2, (6, 4) [Jun 12 17:42:22] DEBUG[2932] chan_iax2.c: Cancelling transmission of packet 1 [Jun 12 17:42:22] DEBUG[2932] chan_iax2.c: Really destroying 1701, having been acked on final message [Jun 12 17:42:22] DEBUG[2932] chan_iax2.c: schedule decrement of callno used for 10.28.130.121 in 60 seconds [Jun 12 17:42:29] DEBUG[2958] chan_sip.c: = Looking for Call ID: KqCXzLqQUjgRo30uuwVP0-BmQ48BBFdd (Checking From) --From tag m7To.422D2vIct7wSeAA0jc9R6KnHaDM --To-tag [Jun 12 17:42:29] DEBUG[2958] acl.c: For destination '10.28.130.142', our source address is '10.28.130.125'. [Jun 12 17:42:29] DEBUG[2958] chan_sip.c: Setting SIP_TRANSPORT_TCP with address 10.28.130.125:5060 [Jun 12 17:42:29] DEBUG[2958] chan_sip.c: Allocating new SIP dialog for KqCXzLqQUjgRo30uuwVP0-BmQ48BBFdd - REGISTER (No RTP) [Jun 12 17:42:29] DEBUG[2958] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Jun 12 17:42:29] DEBUG[2958] netsock2.c: Splitting '10.28.130.142:52052' into... [Jun 12 17:42:29] DEBUG[2958] netsock2.c: ...host '10.28.130.142' and port '52052'. [Jun 12 17:42:29] DEBUG[2958] netsock2.c: Splitting '10.28.130.125' into... [Jun 12 17:42:29] DEBUG[2958] netsock2.c: ...host '10.28.130.125' and port ''. [Jun 12 17:42:29] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:42:29] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '4200' AND host = 'dynamic' [Jun 12 17:42:29] DEBUG[2958] chan_sip.c: -REALTIME- peer built. Name: 4200. Peer objects: 1 [Jun 12 17:42:29] DEBUG[2958] netsock2.c: Splitting '10.28.130.142' into... [Jun 12 17:42:29] DEBUG[2958] netsock2.c: ...host '10.28.130.142' and port ''. [Jun 12 17:42:29] DEBUG[2958] netsock2.c: Splitting '0.0.0.0' into... [Jun 12 17:42:29] DEBUG[2958] netsock2.c: ...host '0.0.0.0' and port ''. [Jun 12 17:42:29] DEBUG[2958] chan_sip.c: -REALTIME- loading peer from database to memory. Name: 4200. Peer objects: 1 [Jun 12 17:42:29] DEBUG[2958] chan_sip.c: Trying to put 'SIP/2.0 401' onto TCP socket destined for 10.28.130.142:52052 [Jun 12 17:42:29] DEBUG[2958] chan_sip.c: Destroying SIP peer 4200 [Jun 12 17:42:29] DEBUG[2958] chan_sip.c: -REALTIME- peer Destroyed. Name: 4200. Realtime Peer objects: 0 [Jun 12 17:42:29] DEBUG[2958] chan_sip.c: = Looking for Call ID: KqCXzLqQUjgRo30uuwVP0-BmQ48BBFdd (Checking From) --From tag m7To.422D2vIct7wSeAA0jc9R6KnHaDM --To-tag [Jun 12 17:42:29] DEBUG[2958] netsock2.c: Splitting '10.28.130.125:5060' into... [Jun 12 17:42:29] DEBUG[2958] netsock2.c: ...host '10.28.130.125' and port '5060'. [Jun 12 17:42:29] DEBUG[2958] netsock2.c: Splitting '10.28.130.125:5060' into... [Jun 12 17:42:29] DEBUG[2958] netsock2.c: ...host '10.28.130.125' and port '5060'. [Jun 12 17:42:29] DEBUG[2958] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Jun 12 17:42:29] DEBUG[2958] netsock2.c: Splitting '10.28.130.142:52052' into... [Jun 12 17:42:29] DEBUG[2958] netsock2.c: ...host '10.28.130.142' and port '52052'. [Jun 12 17:42:29] DEBUG[2958] netsock2.c: Splitting '10.28.130.125' into... [Jun 12 17:42:29] DEBUG[2958] netsock2.c: ...host '10.28.130.125' and port ''. [Jun 12 17:42:29] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:42:29] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '4200' AND host = 'dynamic' [Jun 12 17:42:29] DEBUG[2958] chan_sip.c: -REALTIME- peer built. Name: 4200. Peer objects: 1 [Jun 12 17:42:29] DEBUG[2958] netsock2.c: Splitting '10.28.130.142' into... [Jun 12 17:42:29] DEBUG[2958] netsock2.c: ...host '10.28.130.142' and port ''. [Jun 12 17:42:29] DEBUG[2958] netsock2.c: Splitting '0.0.0.0' into... [Jun 12 17:42:29] DEBUG[2958] netsock2.c: ...host '0.0.0.0' and port ''. [Jun 12 17:42:29] DEBUG[2958] chan_sip.c: -REALTIME- loading peer from database to memory. Name: 4200. Peer objects: 1 [Jun 12 17:42:29] DEBUG[2958] chan_sip.c: Store REGISTER's src-IP:port for call routing. [Jun 12 17:42:29] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:42:29] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Update SQL: UPDATE sipexten SET `ipaddr` = '10.28.130.142', `port` = '52052', `regseconds` = '1371052049', `defaultuser` = '4200', `useragent` = 'Digium D40 1_0_5_46476', `lastms` = '0', `fullcontact` = 'sip:4200@10.28.130.142:5060^3Btransport=TCP^3Bob' WHERE `name` = '4200' [Jun 12 17:42:29] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Updated 1 rows on table: sipexten [Jun 12 17:42:29] DEBUG[2958] chan_sip.c: Trying to put 'SIP/2.0 200' onto TCP socket destined for 10.28.130.142:52052 [Jun 12 17:42:29] DEBUG[2919] devicestate.c: No provider found, checking channel drivers for SIP - 4200 [Jun 12 17:42:29] DEBUG[2919] chan_sip.c: Checking device state for peer 4200 [Jun 12 17:42:29] DEBUG[2958] chan_sip.c: Destroying SIP peer 4200 [Jun 12 17:42:29] DEBUG[2958] chan_sip.c: -REALTIME- peer Destroyed. Name: 4200. Realtime Peer objects: 0 [Jun 12 17:42:29] DEBUG[2919] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:42:29] DEBUG[2919] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '4200' AND host = 'dynamic' [Jun 12 17:42:29] DEBUG[2919] chan_sip.c: -REALTIME- peer built. Name: 4200. Peer objects: 1 [Jun 12 17:42:29] DEBUG[2919] netsock2.c: Splitting '10.28.130.142' into... [Jun 12 17:42:29] DEBUG[2919] netsock2.c: ...host '10.28.130.142' and port ''. [Jun 12 17:42:29] DEBUG[2919] chan_sip.c: Not an IPv4 nor IPv6 address, cannot get port. [Jun 12 17:42:29] DEBUG[2919] chan_sip.c: Not an IPv4 nor IPv6 address, cannot set port. [Jun 12 17:42:29] DEBUG[2919] chan_sip.c: -REALTIME- loading peer from database to memory. Name: 4200. Peer objects: 1 [Jun 12 17:42:29] DEBUG[2919] chan_sip.c: Destroying SIP peer 4200 [Jun 12 17:42:29] DEBUG[2919] chan_sip.c: -REALTIME- peer Destroyed. Name: 4200. Realtime Peer objects: 0 [Jun 12 17:42:29] DEBUG[2919] devicestate.c: Changing state for SIP/4200 - state 1 (Not in use) [Jun 12 17:42:29] DEBUG[2919] devicestate.c: device 'SIP/4200' state '1' [Jun 12 17:42:29] DEBUG[2954] app_queue.c: Device 'SIP/4200' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 12 17:42:29] DEBUG[2958] chan_sip.c: = Looking for Call ID: 8m04fMumDPv88.cB1Pe7qU6r6F5IWAir (Checking From) --From tag bpO-9gidRn4fZV.enQX5MDoyWlAp6UqQ --To-tag [Jun 12 17:42:29] DEBUG[2958] acl.c: For destination '10.28.130.142', our source address is '10.28.130.125'. [Jun 12 17:42:29] DEBUG[2958] chan_sip.c: Setting SIP_TRANSPORT_TCP with address 10.28.130.125:5060 [Jun 12 17:42:29] DEBUG[2958] chan_sip.c: Allocating new SIP dialog for 8m04fMumDPv88.cB1Pe7qU6r6F5IWAir - SUBSCRIBE (No RTP) [Jun 12 17:42:29] DEBUG[2958] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Jun 12 17:42:29] DEBUG[2958] netsock2.c: Splitting '10.28.130.142:52052' into... [Jun 12 17:42:29] DEBUG[2958] netsock2.c: ...host '10.28.130.142' and port '52052'. [Jun 12 17:42:29] DEBUG[2958] chan_sip.c: build_route: Contact hop: "4200" [Jun 12 17:42:29] DEBUG[2958] netsock2.c: Splitting '10.28.130.125' into... [Jun 12 17:42:29] DEBUG[2958] netsock2.c: ...host '10.28.130.125' and port ''. [Jun 12 17:42:29] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:42:29] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '4200' AND host = 'dynamic' [Jun 12 17:42:29] DEBUG[2958] chan_sip.c: -REALTIME- peer built. Name: 4200. Peer objects: 1 [Jun 12 17:42:29] DEBUG[2958] netsock2.c: Splitting '10.28.130.142' into... [Jun 12 17:42:29] DEBUG[2958] netsock2.c: ...host '10.28.130.142' and port ''. [Jun 12 17:42:29] DEBUG[2958] netsock2.c: Splitting '0.0.0.0' into... [Jun 12 17:42:29] DEBUG[2958] netsock2.c: ...host '0.0.0.0' and port ''. [Jun 12 17:42:29] DEBUG[2958] chan_sip.c: -REALTIME- loading peer from database to memory. Name: 4200. Peer objects: 1 [Jun 12 17:42:29] DEBUG[2958] chan_sip.c: Trying to put 'SIP/2.0 401' onto TCP socket destined for 10.28.130.142:52052 [Jun 12 17:42:29] DEBUG[2958] chan_sip.c: Destroying SIP peer 4200 [Jun 12 17:42:29] DEBUG[2958] chan_sip.c: -REALTIME- peer Destroyed. Name: 4200. Realtime Peer objects: 0 [Jun 12 17:42:29] DEBUG[2958] chan_sip.c: = Looking for Call ID: 8m04fMumDPv88.cB1Pe7qU6r6F5IWAir (Checking From) --From tag bpO-9gidRn4fZV.enQX5MDoyWlAp6UqQ --To-tag [Jun 12 17:42:29] DEBUG[2958] netsock2.c: Splitting '10.28.130.125:5060' into... [Jun 12 17:42:29] DEBUG[2958] netsock2.c: ...host '10.28.130.125' and port '5060'. [Jun 12 17:42:29] DEBUG[2958] netsock2.c: Splitting '10.28.130.125:5060' into... [Jun 12 17:42:29] DEBUG[2958] netsock2.c: ...host '10.28.130.125' and port '5060'. [Jun 12 17:42:29] DEBUG[2958] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Jun 12 17:42:29] DEBUG[2958] netsock2.c: Splitting '10.28.130.142:52052' into... [Jun 12 17:42:29] DEBUG[2958] netsock2.c: ...host '10.28.130.142' and port '52052'. [Jun 12 17:42:29] DEBUG[2958] chan_sip.c: build_route: Retaining previous route: [Jun 12 17:42:29] DEBUG[2958] netsock2.c: Splitting '10.28.130.125' into... [Jun 12 17:42:29] DEBUG[2958] netsock2.c: ...host '10.28.130.125' and port ''. [Jun 12 17:42:29] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:42:29] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '4200' AND host = 'dynamic' [Jun 12 17:42:29] DEBUG[2958] chan_sip.c: -REALTIME- peer built. Name: 4200. Peer objects: 1 [Jun 12 17:42:29] DEBUG[2958] netsock2.c: Splitting '10.28.130.142' into... [Jun 12 17:42:29] DEBUG[2958] netsock2.c: ...host '10.28.130.142' and port ''. [Jun 12 17:42:29] DEBUG[2958] netsock2.c: Splitting '0.0.0.0' into... [Jun 12 17:42:29] DEBUG[2958] netsock2.c: ...host '0.0.0.0' and port ''. [Jun 12 17:42:29] DEBUG[2958] chan_sip.c: -REALTIME- loading peer from database to memory. Name: 4200. Peer objects: 1 [Jun 12 17:42:29] DEBUG[2958] chan_sip.c: Trying to put 'SIP/2.0 404' onto TCP socket destined for 10.28.130.142:52052 [Jun 12 17:42:29] NOTICE[2958] chan_sip.c: Received SIP subscribe for peer without mailbox: 4200 [Jun 12 17:42:29] DEBUG[2958] chan_sip.c: Destroying SIP peer 4200 [Jun 12 17:42:29] DEBUG[2958] chan_sip.c: -REALTIME- peer Destroyed. Name: 4200. Realtime Peer objects: 0 [Jun 12 17:42:30] DEBUG[2928] chan_sip.c: Destroying SIP dialog 8m04fMumDPv88.cB1Pe7qU6r6F5IWAir [Jun 12 17:42:30] DEBUG[2958] chan_sip.c: = Looking for Call ID: 0V7ivbXUKPENQpB6yL-CgVsDBKzfRogL (Checking From) --From tag qM3ir9ky3qMdBVPfMqqm9JczSbeDrbqo --To-tag [Jun 12 17:42:30] DEBUG[2958] acl.c: For destination '10.28.130.142', our source address is '10.28.130.125'. [Jun 12 17:42:30] DEBUG[2958] chan_sip.c: Setting SIP_TRANSPORT_TCP with address 10.28.130.125:5060 [Jun 12 17:42:30] DEBUG[2958] chan_sip.c: Allocating new SIP dialog for 0V7ivbXUKPENQpB6yL-CgVsDBKzfRogL - SUBSCRIBE (No RTP) [Jun 12 17:42:30] DEBUG[2958] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Jun 12 17:42:30] DEBUG[2958] netsock2.c: Splitting '10.28.130.142:52052' into... [Jun 12 17:42:30] DEBUG[2958] netsock2.c: ...host '10.28.130.142' and port '52052'. [Jun 12 17:42:30] DEBUG[2958] chan_sip.c: build_route: Contact hop: "4200" [Jun 12 17:42:30] DEBUG[2958] netsock2.c: Splitting '10.28.130.125' into... [Jun 12 17:42:30] DEBUG[2958] netsock2.c: ...host '10.28.130.125' and port ''. [Jun 12 17:42:30] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:42:30] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '4200' AND host = 'dynamic' [Jun 12 17:42:30] DEBUG[2958] chan_sip.c: -REALTIME- peer built. Name: 4200. Peer objects: 1 [Jun 12 17:42:30] DEBUG[2958] netsock2.c: Splitting '10.28.130.142' into... [Jun 12 17:42:30] DEBUG[2958] netsock2.c: ...host '10.28.130.142' and port ''. [Jun 12 17:42:30] DEBUG[2958] netsock2.c: Splitting '0.0.0.0' into... [Jun 12 17:42:30] DEBUG[2958] netsock2.c: ...host '0.0.0.0' and port ''. [Jun 12 17:42:30] DEBUG[2958] chan_sip.c: -REALTIME- loading peer from database to memory. Name: 4200. Peer objects: 1 [Jun 12 17:42:30] DEBUG[2958] chan_sip.c: Trying to put 'SIP/2.0 401' onto TCP socket destined for 10.28.130.142:52052 [Jun 12 17:42:30] DEBUG[2958] chan_sip.c: Destroying SIP peer 4200 [Jun 12 17:42:30] DEBUG[2958] chan_sip.c: -REALTIME- peer Destroyed. Name: 4200. Realtime Peer objects: 0 [Jun 12 17:42:30] DEBUG[2958] chan_sip.c: = Looking for Call ID: 0V7ivbXUKPENQpB6yL-CgVsDBKzfRogL (Checking From) --From tag qM3ir9ky3qMdBVPfMqqm9JczSbeDrbqo --To-tag [Jun 12 17:42:30] DEBUG[2958] netsock2.c: Splitting '10.28.130.125:5060' into... [Jun 12 17:42:30] DEBUG[2958] netsock2.c: ...host '10.28.130.125' and port '5060'. [Jun 12 17:42:30] DEBUG[2958] netsock2.c: Splitting '10.28.130.125:5060' into... [Jun 12 17:42:30] DEBUG[2958] netsock2.c: ...host '10.28.130.125' and port '5060'. [Jun 12 17:42:30] DEBUG[2958] chan_sip.c: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Jun 12 17:42:30] DEBUG[2958] netsock2.c: Splitting '10.28.130.142:52052' into... [Jun 12 17:42:30] DEBUG[2958] netsock2.c: ...host '10.28.130.142' and port '52052'. [Jun 12 17:42:30] DEBUG[2958] chan_sip.c: build_route: Retaining previous route: [Jun 12 17:42:30] DEBUG[2958] netsock2.c: Splitting '10.28.130.125' into... [Jun 12 17:42:30] DEBUG[2958] netsock2.c: ...host '10.28.130.125' and port ''. [Jun 12 17:42:30] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:42:30] DEBUG[2958] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '4200' AND host = 'dynamic' [Jun 12 17:42:30] DEBUG[2958] chan_sip.c: -REALTIME- peer built. Name: 4200. Peer objects: 1 [Jun 12 17:42:30] DEBUG[2958] netsock2.c: Splitting '10.28.130.142' into... [Jun 12 17:42:30] DEBUG[2958] netsock2.c: ...host '10.28.130.142' and port ''. [Jun 12 17:42:30] DEBUG[2958] netsock2.c: Splitting '0.0.0.0' into... [Jun 12 17:42:30] DEBUG[2958] netsock2.c: ...host '0.0.0.0' and port ''. [Jun 12 17:42:30] DEBUG[2958] chan_sip.c: -REALTIME- loading peer from database to memory. Name: 4200. Peer objects: 1 [Jun 12 17:42:30] DEBUG[2958] netsock2.c: Splitting '10.28.130.125:5060' into... [Jun 12 17:42:30] DEBUG[2958] netsock2.c: ...host '10.28.130.125' and port ''. [Jun 12 17:42:30] DEBUG[2958] netsock2.c: Splitting '10.28.130.125' into... [Jun 12 17:42:30] DEBUG[2958] netsock2.c: ...host '10.28.130.125' and port ''. [Jun 12 17:42:30] DEBUG[2958] chan_sip.c: Trying to put 'SIP/2.0 404' onto TCP socket destined for 10.28.130.142:52052 [Jun 12 17:42:30] DEBUG[2958] chan_sip.c: Destroying SIP peer 4200 [Jun 12 17:42:30] DEBUG[2958] chan_sip.c: -REALTIME- peer Destroyed. Name: 4200. Realtime Peer objects: 0 [Jun 12 17:42:31] DEBUG[2928] chan_sip.c: Destroying SIP dialog 0V7ivbXUKPENQpB6yL-CgVsDBKzfRogL [Jun 12 17:42:32] DEBUG[2930] chan_iax2.c: ip callno count decremented to 1 for 10.28.130.121 [Jun 12 17:42:36] DEBUG[2928] chan_sip.c: Auto destroying SIP dialog '3168827b0300bc7455c86a247f978468@10.28.130.121' [Jun 12 17:42:36] DEBUG[2928] chan_sip.c: Destroying SIP dialog 3168827b0300bc7455c86a247f978468@10.28.130.121 [Jun 12 17:42:44] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:42:44] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '10.28.130.121' AND host = 'dynamic' [Jun 12 17:42:44] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:42:44] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '10.28.130.121' [Jun 12 17:42:44] DEBUG[2928] chan_sip.c: SIP Registry 10.28.130.121: refcount now 3 [Jun 12 17:42:44] DEBUG[2928] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:42:44] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:42:44] DEBUG[2928] chan_sip.c: SIP Registry 10.28.130.121: refcount now 2 [Jun 12 17:42:44] DEBUG[2928] chan_sip.c: Allocating new SIP dialog for 0df587045630ad970a2a21583d853f9f@10.28.130.125 - REGISTER (No RTP) [Jun 12 17:42:44] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:42:44] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '10.28.130.121' AND host = 'dynamic' [Jun 12 17:42:44] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:42:44] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '10.28.130.121' [Jun 12 17:42:44] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:42:44] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '10.28.130.121' AND host = 'dynamic' [Jun 12 17:42:44] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:42:44] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '10.28.130.121' [Jun 12 17:42:44] DEBUG[2928] chan_sip.c: SIP Registry 10.28.130.121: refcount now 3 [Jun 12 17:42:44] DEBUG[2928] acl.c: For destination '10.28.130.121', our source address is '10.28.130.125'. [Jun 12 17:42:44] DEBUG[2928] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 10.28.130.125:5060 [Jun 12 17:42:44] DEBUG[2928] chan_sip.c: SIP Registry 10.28.130.121: refcount now 4 [Jun 12 17:42:44] DEBUG[2928] chan_sip.c: Scheduled a registration timeout for 10.28.130.121 id #48842 [Jun 12 17:42:44] DEBUG[2928] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:42:44] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:42:44] DEBUG[2928] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:42:44] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:42:44] DEBUG[2928] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:42:44] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:42:44] DEBUG[2928] chan_sip.c: Initializing initreq for method REGISTER - callid 0df587045630ad970a2a21583d853f9f@10.28.130.125 [Jun 12 17:42:44] DEBUG[2928] chan_sip.c: REGISTER attempt 1 to 2997@10.28.130.121 [Jun 12 17:42:44] DEBUG[2928] chan_sip.c: Trying to put 'REGISTER si' onto UDP socket destined for 10.28.130.121:5060 [Jun 12 17:42:44] DEBUG[2928] chan_sip.c: SIP Registry 10.28.130.121: refcount now 3 [Jun 12 17:42:44] DEBUG[2928] chan_sip.c: = Looking for Call ID: 0df587045630ad970a2a21583d853f9f@10.28.130.125 (Checking To) --From tag as437833be --To-tag as0287e456 [Jun 12 17:42:44] DEBUG[2928] chan_sip.c: Stopping retransmission on '0df587045630ad970a2a21583d853f9f@10.28.130.125' of Request 10018: Match Found [Jun 12 17:42:44] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:42:44] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '10.28.130.121' AND host = 'dynamic' [Jun 12 17:42:44] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Connection okay. [Jun 12 17:42:44] DEBUG[2928] res_config_mysql.c: MySQL RealTime: Retrieve SQL: SELECT * FROM sipexten WHERE name = '10.28.130.121' [Jun 12 17:42:44] DEBUG[2928] chan_sip.c: SIP Registry 10.28.130.121: refcount now 4 [Jun 12 17:42:44] DEBUG[2928] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:42:44] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:42:44] DEBUG[2928] chan_sip.c: SIP Registry 10.28.130.121: refcount now 3 [Jun 12 17:42:44] DEBUG[2928] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:42:44] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:42:44] DEBUG[2928] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:42:44] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:42:44] DEBUG[2928] netsock2.c: Splitting '10.28.130.121' into... [Jun 12 17:42:44] DEBUG[2928] netsock2.c: ...host '10.28.130.121' and port ''. [Jun 12 17:42:44] DEBUG[2928] chan_sip.c: Initializing already initialized SIP dialog 0df587045630ad970a2a21583d853f9f@10.28.130.125 (presumably reinvite) [Jun 12 17:42:44] DEBUG[2928] chan_sip.c: REGISTER attempt 2 to 2997@10.28.130.121 [Jun 12 17:42:44] DEBUG[2928] chan_sip.c: Trying to put 'REGISTER si' onto UDP socket destined for 10.28.130.121:5060 [Jun 12 17:42:44] DEBUG[2928] chan_sip.c: = Looking for Call ID: 0df587045630ad970a2a21583d853f9f@10.28.130.125 (Checking To) --From tag as581c94ed --To-tag as0287e456 [Jun 12 17:42:44] DEBUG[2928] chan_sip.c: Stopping retransmission on '0df587045630ad970a2a21583d853f9f@10.28.130.125' of Request 10019: Match Found [Jun 12 17:42:44] DEBUG[2928] chan_sip.c: Registration successful [Jun 12 17:42:44] DEBUG[2928] chan_sip.c: Cancelling timeout 48842 [Jun 12 17:42:44] DEBUG[2928] chan_sip.c: SIP Registry 10.28.130.121: refcount now 2 [Jun 12 17:42:44] DEBUG[2928] chan_sip.c: SIP Registry 10.28.130.121: refcount now 1 [Jun 12 17:42:44] DEBUG[2928] chan_sip.c: SIP Registry 10.28.130.121: refcount now 2 [Jun 12 17:43:57] NOTICE[2958] chan_sip.c: Received SIP subscribe for peer without mailbox: 4200 [Jun 12 17:44:59] NOTICE[2958] chan_sip.c: Received SIP subscribe for peer without mailbox: 4200 [Jun 12 17:47:29] NOTICE[2958] chan_sip.c: Received SIP subscribe for peer without mailbox: 4200 [Jun 12 17:48:57] NOTICE[2958] chan_sip.c: Received SIP subscribe for peer without mailbox: 4200 [Jun 12 17:49:59] NOTICE[2958] chan_sip.c: Received SIP subscribe for peer without mailbox: 4200 [Jun 12 17:52:29] NOTICE[2958] chan_sip.c: Received SIP subscribe for peer without mailbox: 4200 [Jun 12 17:53:57] NOTICE[2958] chan_sip.c: Received SIP subscribe for peer without mailbox: 4200 [Jun 12 17:54:59] NOTICE[2958] chan_sip.c: Received SIP subscribe for peer without mailbox: 4200 [Jun 12 17:57:29] NOTICE[2958] chan_sip.c: Received SIP subscribe for peer without mailbox: 4200 [Jun 12 17:58:57] NOTICE[2958] chan_sip.c: Received SIP subscribe for peer without mailbox: 4200