Jun 14 10:24:17 VERBOSE[4101]: Sip read: INVITE sip:8@192.168.233.66 SIP/2.0 Via: SIP/2.0/UDP 192.168.233.67;branch=z9hG4bK31cca5d419cb4514 From: "Holger Schurig" ;tag=8ceda10af2df82b9 To: Contact: Call-ID: a8f9fd1d2aee1e1f@192.168.233.67 CSeq: 44562 INVITE User-Agent: Grandstream BT100 1.0.5.0 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Content-Type: application/sdp Content-Length: 175 v=0 o=hschurig 8000 8000 IN IP4 192.168.233.67 s=SIP Call c=IN IP4 192.168.233.67 t=0 0 m=audio 5004 RTP/AVP 8 0 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=ptime:20 Jun 14 10:24:17 VERBOSE[4101]: 12 headers, 9 lines Jun 14 10:24:17 DEBUG[4101]: Allocating new SIP call for a8f9fd1d2aee1e1f@192.168.233.67 Jun 14 10:24:17 VERBOSE[4101]: Using latest request as basis request Jun 14 10:24:17 VERBOSE[4101]: Sending to 192.168.233.67 : 5060 (non-NAT) Jun 14 10:24:17 VERBOSE[4101]: Found RTP audio format 8 Jun 14 10:24:17 VERBOSE[4101]: Found RTP audio format 0 Jun 14 10:24:17 VERBOSE[4101]: Peer RTP is at port 192.168.233.67:0 Jun 14 10:24:17 VERBOSE[4101]: Found description format PCMA Jun 14 10:24:17 VERBOSE[4101]: Found description format PCMU Jun 14 10:24:17 VERBOSE[4101]: Capabilities: us - 0x40c(ULAW|ALAW|ILBC), peer - audio=0xc(ULAW|ALAW)/video=0x0(EMPTY), combined - 0xc(ULAW|ALAW) Jun 14 10:24:17 VERBOSE[4101]: Non-codec capabilities: us - 0x1(G723), peer - 0x0(EMPTY), combined - 0x0(EMPTY) Jun 14 10:24:17 VERBOSE[4101]: Found peer 'hschurig' Jun 14 10:24:17 DEBUG[4101]: Setting NAT on RTP to 0 Jun 14 10:24:17 DEBUG[4101]: Check for res for hschurig Jun 14 10:24:17 DEBUG[4101]: hschurig is not a local user Jun 14 10:24:17 VERBOSE[4101]: Looking for 8 in default Jun 14 10:24:17 VERBOSE[4101]: Reliably Transmitting (no NAT): SIP/2.0 484 Address Incomplete Via: SIP/2.0/UDP 192.168.233.67;branch=z9hG4bK31cca5d419cb4514 From: "Holger Schurig" ;tag=8ceda10af2df82b9 To: ;tag=as2c310453 Call-ID: a8f9fd1d2aee1e1f@192.168.233.67 CSeq: 44562 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER Contact: Content-Length: 0 to 192.168.233.67:5060 Jun 14 10:24:17 DEBUG[4101]: hschurig is not a local user Jun 14 10:24:17 VERBOSE[4101]: Sip read: ACK sip:8@192.168.233.66:0 SIP/2.0 Via: SIP/2.0/UDP 192.168.233.67;branch=z9hG4bK31cca5d419cb4514 From: "Holger Schurig" ;tag=8ceda10af2df82b9 To: ;tag=as2c310453 Contact: Call-ID: a8f9fd1d2aee1e1f@192.168.233.67 CSeq: 44562 ACK User-Agent: Grandstream BT100 1.0.5.0 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Content-Length: 0 Jun 14 10:24:17 VERBOSE[4101]: 11 headers, 0 lines Jun 14 10:24:17 DEBUG[4101]: Stopping retransmission on 'a8f9fd1d2aee1e1f@192.168.233.67' of Response 44562: Found Jun 14 10:24:17 VERBOSE[4101]: Destroying call 'a8f9fd1d2aee1e1f@192.168.233.67' Jun 14 10:24:18 VERBOSE[4101]: Sip read: INVITE sip:89@192.168.233.66 SIP/2.0 Via: SIP/2.0/UDP 192.168.233.67;branch=z9hG4bK23b6b7e109bca7b9 From: "Holger Schurig" ;tag=8ceda10af2df82b9 To: Contact: Call-ID: a8f9fd1d2aee1e1f@192.168.233.67 CSeq: 44563 INVITE User-Agent: Grandstream BT100 1.0.5.0 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Content-Type: application/sdp Content-Length: 175 v=0 o=hschurig 8000 8000 IN IP4 192.168.233.67 s=SIP Call c=IN IP4 192.168.233.67 t=0 0 m=audio 5004 RTP/AVP 8 0 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=ptime:20 Jun 14 10:24:18 VERBOSE[4101]: 12 headers, 9 lines Jun 14 10:24:18 DEBUG[4101]: Allocating new SIP call for a8f9fd1d2aee1e1f@192.168.233.67 Jun 14 10:24:18 VERBOSE[4101]: Using latest request as basis request Jun 14 10:24:18 VERBOSE[4101]: Sending to 192.168.233.67 : 5060 (non-NAT) Jun 14 10:24:18 VERBOSE[4101]: Found RTP audio format 8 Jun 14 10:24:18 VERBOSE[4101]: Found RTP audio format 0 Jun 14 10:24:18 VERBOSE[4101]: Peer RTP is at port 192.168.233.67:0 Jun 14 10:24:18 VERBOSE[4101]: Found description format PCMA Jun 14 10:24:18 VERBOSE[4101]: Found description format PCMU Jun 14 10:24:18 VERBOSE[4101]: Capabilities: us - 0x40c(ULAW|ALAW|ILBC), peer - audio=0xc(ULAW|ALAW)/video=0x0(EMPTY), combined - 0xc(ULAW|ALAW) Jun 14 10:24:18 VERBOSE[4101]: Non-codec capabilities: us - 0x1(G723), peer - 0x0(EMPTY), combined - 0x0(EMPTY) Jun 14 10:24:18 VERBOSE[4101]: Found peer 'hschurig' Jun 14 10:24:18 DEBUG[4101]: Setting NAT on RTP to 0 Jun 14 10:24:18 DEBUG[4101]: Check for res for hschurig Jun 14 10:24:18 DEBUG[4101]: hschurig is not a local user Jun 14 10:24:18 VERBOSE[4101]: Looking for 89 in default Jun 14 10:24:18 VERBOSE[4101]: Reliably Transmitting (no NAT): SIP/2.0 484 Address Incomplete Via: SIP/2.0/UDP 192.168.233.67;branch=z9hG4bK23b6b7e109bca7b9 From: "Holger Schurig" ;tag=8ceda10af2df82b9 To: ;tag=as436dbfa9 Call-ID: a8f9fd1d2aee1e1f@192.168.233.67 CSeq: 44563 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER Contact: Content-Length: 0 to 192.168.233.67:5060 Jun 14 10:24:18 DEBUG[4101]: hschurig is not a local user Jun 14 10:24:18 VERBOSE[4101]: Sip read: ACK sip:89@192.168.233.66:0 SIP/2.0 Via: SIP/2.0/UDP 192.168.233.67;branch=z9hG4bK23b6b7e109bca7b9 From: "Holger Schurig" ;tag=8ceda10af2df82b9 To: ;tag=as436dbfa9 Contact: Call-ID: a8f9fd1d2aee1e1f@192.168.233.67 CSeq: 44563 ACK User-Agent: Grandstream BT100 1.0.5.0 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Content-Length: 0 Jun 14 10:24:18 VERBOSE[4101]: 11 headers, 0 lines Jun 14 10:24:18 DEBUG[4101]: Stopping retransmission on 'a8f9fd1d2aee1e1f@192.168.233.67' of Response 44563: Found Jun 14 10:24:18 VERBOSE[4101]: Destroying call 'a8f9fd1d2aee1e1f@192.168.233.67' Jun 14 10:24:19 VERBOSE[4101]: Sip read: INVITE sip:899@192.168.233.66 SIP/2.0 Via: SIP/2.0/UDP 192.168.233.67;branch=z9hG4bK1b1c8a6caf8bd5d3 From: "Holger Schurig" ;tag=8ceda10af2df82b9 To: Contact: Call-ID: a8f9fd1d2aee1e1f@192.168.233.67 CSeq: 44564 INVITE User-Agent: Grandstream BT100 1.0.5.0 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Content-Type: application/sdp Content-Length: 175 v=0 o=hschurig 8000 8000 IN IP4 192.168.233.67 s=SIP Call c=IN IP4 192.168.233.67 t=0 0 m=audio 5004 RTP/AVP 8 0 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=ptime:20 Jun 14 10:24:19 VERBOSE[4101]: 12 headers, 9 lines Jun 14 10:24:19 DEBUG[4101]: Allocating new SIP call for a8f9fd1d2aee1e1f@192.168.233.67 Jun 14 10:24:19 VERBOSE[4101]: Using latest request as basis request Jun 14 10:24:19 VERBOSE[4101]: Sending to 192.168.233.67 : 5060 (non-NAT) Jun 14 10:24:19 VERBOSE[4101]: Found RTP audio format 8 Jun 14 10:24:19 VERBOSE[4101]: Found RTP audio format 0 Jun 14 10:24:19 VERBOSE[4101]: Peer RTP is at port 192.168.233.67:0 Jun 14 10:24:19 VERBOSE[4101]: Found description format PCMA Jun 14 10:24:19 VERBOSE[4101]: Found description format PCMU Jun 14 10:24:19 VERBOSE[4101]: Capabilities: us - 0x40c(ULAW|ALAW|ILBC), peer - audio=0xc(ULAW|ALAW)/video=0x0(EMPTY), combined - 0xc(ULAW|ALAW) Jun 14 10:24:19 VERBOSE[4101]: Non-codec capabilities: us - 0x1(G723), peer - 0x0(EMPTY), combined - 0x0(EMPTY) Jun 14 10:24:19 VERBOSE[4101]: Found peer 'hschurig' Jun 14 10:24:19 DEBUG[4101]: Setting NAT on RTP to 0 Jun 14 10:24:19 DEBUG[4101]: Check for res for hschurig Jun 14 10:24:19 DEBUG[4101]: hschurig is not a local user Jun 14 10:24:19 VERBOSE[4101]: Looking for 899 in default Jun 14 10:24:19 DEBUG[4101]: build_route: Contact hop: Jun 14 10:24:19 VERBOSE[4101]: list_route: hop: Jun 14 10:24:19 VERBOSE[4101]: Transmitting (no NAT): SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.233.67;branch=z9hG4bK1b1c8a6caf8bd5d3 From: "Holger Schurig" ;tag=8ceda10af2df82b9 To: ;tag=as3647a28c Call-ID: a8f9fd1d2aee1e1f@192.168.233.67 CSeq: 44564 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER Contact: Content-Length: 0 to 192.168.233.67:5060 Jun 14 10:24:19 DEBUG[6151]: Launching 'SetCIDNum' Jun 14 10:24:19 DEBUG[6151]: Launching 'SetCIDName' Jun 14 10:24:19 DEBUG[6151]: Launching 'Dial' Jun 14 10:24:19 DEBUG[6151]: SIMPLE DIAL (NO URL) Jun 14 10:24:19 DEBUG[6151]: New max nontrunk callno is 3 Jun 14 10:24:19 DEBUG[6151]: Creating new call structure 2 Jun 14 10:24:19 DEBUG[5126]: Sending 4 on 2/0 to 65.39.205.121:4569 Jun 14 10:24:19 VERBOSE[6151]: -- Called 254041:popo12@iax2.fwdnet.net/9 Jun 14 10:24:19 VERBOSE[6151]: Transmitting (no NAT): SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.233.67;branch=z9hG4bK1b1c8a6caf8bd5d3 From: "Holger Schurig" ;tag=8ceda10af2df82b9 To: ;tag=as3647a28c Call-ID: a8f9fd1d2aee1e1f@192.168.233.67 CSeq: 44564 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER Contact: Content-Length: 0 to 192.168.233.67:5060 Jun 14 10:24:19 DEBUG[5126]: Received packet 0, (6, 8) Jun 14 10:24:19 DEBUG[5126]: Cancelling transmission of packet 0 Jun 14 10:24:19 DEBUG[5126]: IAX subclass 8 received Jun 14 10:24:19 DEBUG[5126]: min = 0, max = 0, jb = 0, lateness = -16 Jun 14 10:24:19 DEBUG[5126]: Sending 151 on 2/32 to 65.39.205.121:4569 Jun 14 10:24:19 DEBUG[5126]: Received packet 1, (6, 6) Jun 14 10:24:19 DEBUG[5126]: Cancelling transmission of packet 1 Jun 14 10:24:19 DEBUG[5126]: IAX subclass 6 received Jun 14 10:24:19 DEBUG[5126]: min = 0, max = 0, jb = 0, lateness = -16 Jun 14 10:24:19 WARNING[5126]: Call rejected by 65.39.205.121: No such context/extension Jun 14 10:24:19 DEBUG[5126]: Immediately destroying 2, having received reject Jun 14 10:24:19 DEBUG[5126]: Sending 162 on 2/32 to 65.39.205.121:4569 Jun 14 10:24:19 DEBUG[6151]: Hanging up channel 'IAX2[65.39.205.121:4569]/2' Jun 14 10:24:19 DEBUG[6151]: We're hanging up IAX2[65.39.205.121:4569]/2 now... Jun 14 10:24:19 DEBUG[6151]: Really destroying IAX2[65.39.205.121:4569]/2 now... Jun 14 10:24:19 VERBOSE[6151]: -- Hungup 'IAX2[65.39.205.121:4569]/2' Jun 14 10:24:19 VERBOSE[6151]: == No one is available to answer at this time Jun 14 10:24:19 DEBUG[6151]: Launching 'Congestion' Jun 14 10:24:19 VERBOSE[6151]: Transmitting (no NAT): SIP/2.0 503 Service Unavailable Via: SIP/2.0/UDP 192.168.233.67;branch=z9hG4bK1b1c8a6caf8bd5d3 From: "Holger Schurig" ;tag=8ceda10af2df82b9 To: ;tag=as3647a28c Call-ID: a8f9fd1d2aee1e1f@192.168.233.67 CSeq: 44564 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER Contact: Content-Length: 0 to 192.168.233.67:5060 Jun 14 10:24:19 DEBUG[6151]: Soft-Hanging up channel 'SIP/hschurig-e32c' Jun 14 10:24:19 DEBUG[6151]: Spawn extension (default,899,4) exited non-zero on 'SIP/hschurig-e32c' Jun 14 10:24:19 DEBUG[6151]: Hanging up channel 'SIP/hschurig-e32c' Jun 14 10:24:19 DEBUG[6151]: sip_hangup(SIP/hschurig-e32c) Jun 14 10:24:19 DEBUG[6151]: update_user_counter(hschurig) - decrement inUse counter Jun 14 10:24:19 DEBUG[6151]: hschurig is not a local user Jun 14 10:24:19 VERBOSE[4101]: Sip read: ACK sip:899@192.168.233.66:0 SIP/2.0 Via: SIP/2.0/UDP 192.168.233.67;branch=z9hG4bK1b1c8a6caf8bd5d3 From: "Holger Schurig" ;tag=8ceda10af2df82b9 To: ;tag=as3647a28c Contact: Call-ID: a8f9fd1d2aee1e1f@192.168.233.67 CSeq: 44564 ACK User-Agent: Grandstream BT100 1.0.5.0 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Content-Length: 0 Jun 14 10:24:19 VERBOSE[4101]: 11 headers, 0 lines Jun 14 10:24:19 DEBUG[4101]: Stopping retransmission on 'a8f9fd1d2aee1e1f@192.168.233.67' of Response 44564: Not Found Jun 14 10:24:19 VERBOSE[4101]: Destroying call 'a8f9fd1d2aee1e1f@192.168.233.67' Jun 14 10:24:20 VERBOSE[4101]: Sip read: INVITE sip:8995@192.168.233.66 SIP/2.0 Via: SIP/2.0/UDP 192.168.233.67;branch=z9hG4bK1491e196e9975594 From: "Holger Schurig" ;tag=8ceda10af2df82b9 To: Contact: Call-ID: a8f9fd1d2aee1e1f@192.168.233.67 CSeq: 44565 INVITE User-Agent: Grandstream BT100 1.0.5.0 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Content-Type: application/sdp Content-Length: 175 v=0 o=hschurig 8000 8000 IN IP4 192.168.233.67 s=SIP Call c=IN IP4 192.168.233.67 t=0 0 m=audio 5004 RTP/AVP 8 0 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=ptime:20 Jun 14 10:24:20 VERBOSE[4101]: 12 headers, 9 lines Jun 14 10:24:20 DEBUG[4101]: Allocating new SIP call for a8f9fd1d2aee1e1f@192.168.233.67 Jun 14 10:24:20 VERBOSE[4101]: Using latest request as basis request Jun 14 10:24:20 VERBOSE[4101]: Sending to 192.168.233.67 : 5060 (non-NAT) Jun 14 10:24:20 VERBOSE[4101]: Found RTP audio format 8 Jun 14 10:24:20 VERBOSE[4101]: Found RTP audio format 0 Jun 14 10:24:20 VERBOSE[4101]: Peer RTP is at port 192.168.233.67:0 Jun 14 10:24:20 VERBOSE[4101]: Found description format PCMA Jun 14 10:24:20 VERBOSE[4101]: Found description format PCMU Jun 14 10:24:20 VERBOSE[4101]: Capabilities: us - 0x40c(ULAW|ALAW|ILBC), peer - audio=0xc(ULAW|ALAW)/video=0x0(EMPTY), combined - 0xc(ULAW|ALAW) Jun 14 10:24:20 VERBOSE[4101]: Non-codec capabilities: us - 0x1(G723), peer - 0x0(EMPTY), combined - 0x0(EMPTY) Jun 14 10:24:20 VERBOSE[4101]: Found peer 'hschurig' Jun 14 10:24:20 DEBUG[4101]: Setting NAT on RTP to 0 Jun 14 10:24:20 DEBUG[4101]: Check for res for hschurig Jun 14 10:24:20 DEBUG[4101]: hschurig is not a local user Jun 14 10:24:20 VERBOSE[4101]: Looking for 8995 in default Jun 14 10:24:20 DEBUG[4101]: build_route: Contact hop: Jun 14 10:24:20 VERBOSE[4101]: list_route: hop: Jun 14 10:24:20 VERBOSE[4101]: Transmitting (no NAT): SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.233.67;branch=z9hG4bK1491e196e9975594 From: "Holger Schurig" ;tag=8ceda10af2df82b9 To: ;tag=as79f63e87 Call-ID: a8f9fd1d2aee1e1f@192.168.233.67 CSeq: 44565 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER Contact: Content-Length: 0 to 192.168.233.67:5060 Jun 14 10:24:20 DEBUG[7175]: Launching 'SetCIDNum' Jun 14 10:24:20 DEBUG[7175]: Launching 'SetCIDName' Jun 14 10:24:20 DEBUG[7175]: Launching 'Dial' Jun 14 10:24:20 DEBUG[7175]: SIMPLE DIAL (NO URL) Jun 14 10:24:20 DEBUG[7175]: New max nontrunk callno is 4 Jun 14 10:24:20 DEBUG[7175]: Creating new call structure 3 Jun 14 10:24:20 DEBUG[5126]: Sending 3 on 3/0 to 65.39.205.121:4569 Jun 14 10:24:20 VERBOSE[7175]: -- Called 254041:popo12@iax2.fwdnet.net/95 Jun 14 10:24:20 VERBOSE[7175]: Transmitting (no NAT): SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.233.67;branch=z9hG4bK1491e196e9975594 From: "Holger Schurig" ;tag=8ceda10af2df82b9 To: ;tag=as79f63e87 Call-ID: a8f9fd1d2aee1e1f@192.168.233.67 CSeq: 44565 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER Contact: Content-Length: 0 to 192.168.233.67:5060 Jun 14 10:24:20 DEBUG[5126]: Received packet 0, (6, 8) Jun 14 10:24:20 DEBUG[5126]: Cancelling transmission of packet 0 Jun 14 10:24:20 DEBUG[5126]: IAX subclass 8 received Jun 14 10:24:20 DEBUG[5126]: min = 0, max = 0, jb = 0, lateness = -15 Jun 14 10:24:20 DEBUG[5126]: Sending 149 on 3/229 to 65.39.205.121:4569 Jun 14 10:24:20 DEBUG[5126]: Received packet 1, (6, 6) Jun 14 10:24:20 DEBUG[5126]: Cancelling transmission of packet 1 Jun 14 10:24:20 DEBUG[5126]: IAX subclass 6 received Jun 14 10:24:20 DEBUG[5126]: min = 0, max = 0, jb = 0, lateness = -15 Jun 14 10:24:20 WARNING[5126]: Call rejected by 65.39.205.121: No such context/extension Jun 14 10:24:20 DEBUG[5126]: Immediately destroying 3, having received reject Jun 14 10:24:20 DEBUG[5126]: Sending 160 on 3/229 to 65.39.205.121:4569 Jun 14 10:24:20 DEBUG[7175]: Hanging up channel 'IAX2[65.39.205.121:4569]/3' Jun 14 10:24:20 DEBUG[7175]: We're hanging up IAX2[65.39.205.121:4569]/3 now... Jun 14 10:24:20 DEBUG[7175]: Really destroying IAX2[65.39.205.121:4569]/3 now... Jun 14 10:24:20 VERBOSE[7175]: -- Hungup 'IAX2[65.39.205.121:4569]/3' Jun 14 10:24:20 VERBOSE[7175]: == No one is available to answer at this time Jun 14 10:24:20 DEBUG[7175]: Launching 'Congestion' Jun 14 10:24:20 VERBOSE[7175]: Transmitting (no NAT): SIP/2.0 503 Service Unavailable Via: SIP/2.0/UDP 192.168.233.67;branch=z9hG4bK1491e196e9975594 From: "Holger Schurig" ;tag=8ceda10af2df82b9 To: ;tag=as79f63e87 Call-ID: a8f9fd1d2aee1e1f@192.168.233.67 CSeq: 44565 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER Contact: Content-Length: 0 to 192.168.233.67:5060 Jun 14 10:24:20 DEBUG[7175]: Soft-Hanging up channel 'SIP/hschurig-56ef' Jun 14 10:24:20 DEBUG[7175]: Spawn extension (default,8995,4) exited non-zero on 'SIP/hschurig-56ef' Jun 14 10:24:20 DEBUG[7175]: Hanging up channel 'SIP/hschurig-56ef' Jun 14 10:24:20 DEBUG[7175]: sip_hangup(SIP/hschurig-56ef) Jun 14 10:24:20 DEBUG[7175]: update_user_counter(hschurig) - decrement inUse counter Jun 14 10:24:20 DEBUG[7175]: hschurig is not a local user Jun 14 10:24:20 VERBOSE[4101]: Sip read: ACK sip:8995@192.168.233.66:0 SIP/2.0 Via: SIP/2.0/UDP 192.168.233.67;branch=z9hG4bK1491e196e9975594 From: "Holger Schurig" ;tag=8ceda10af2df82b9 To: ;tag=as79f63e87 Contact: Call-ID: a8f9fd1d2aee1e1f@192.168.233.67 CSeq: 44565 ACK User-Agent: Grandstream BT100 1.0.5.0 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Content-Length: 0 Jun 14 10:24:20 VERBOSE[4101]: 11 headers, 0 lines Jun 14 10:24:20 DEBUG[4101]: Stopping retransmission on 'a8f9fd1d2aee1e1f@192.168.233.67' of Response 44565: Not Found Jun 14 10:24:20 VERBOSE[4101]: Destroying call 'a8f9fd1d2aee1e1f@192.168.233.67' Jun 14 10:24:21 VERBOSE[4101]: Sip read: INVITE sip:89958@192.168.233.66 SIP/2.0 Via: SIP/2.0/UDP 192.168.233.67;branch=z9hG4bK7dfefb472500b0b8 From: "Holger Schurig" ;tag=8ceda10af2df82b9 To: Contact: Call-ID: a8f9fd1d2aee1e1f@192.168.233.67 CSeq: 44566 INVITE User-Agent: Grandstream BT100 1.0.5.0 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Content-Type: application/sdp Content-Length: 175 v=0 o=hschurig 8000 8000 IN IP4 192.168.233.67 s=SIP Call c=IN IP4 192.168.233.67 t=0 0 m=audio 5004 RTP/AVP 8 0 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=ptime:20 Jun 14 10:24:21 VERBOSE[4101]: 12 headers, 9 lines Jun 14 10:24:21 DEBUG[4101]: Allocating new SIP call for a8f9fd1d2aee1e1f@192.168.233.67 Jun 14 10:24:21 VERBOSE[4101]: Using latest request as basis request Jun 14 10:24:21 VERBOSE[4101]: Sending to 192.168.233.67 : 5060 (non-NAT) Jun 14 10:24:21 VERBOSE[4101]: Found RTP audio format 8 Jun 14 10:24:21 VERBOSE[4101]: Found RTP audio format 0 Jun 14 10:24:21 VERBOSE[4101]: Peer RTP is at port 192.168.233.67:0 Jun 14 10:24:21 VERBOSE[4101]: Found description format PCMA Jun 14 10:24:21 VERBOSE[4101]: Found description format PCMU Jun 14 10:24:21 VERBOSE[4101]: Capabilities: us - 0x40c(ULAW|ALAW|ILBC), peer - audio=0xc(ULAW|ALAW)/video=0x0(EMPTY), combined - 0xc(ULAW|ALAW) Jun 14 10:24:21 VERBOSE[4101]: Non-codec capabilities: us - 0x1(G723), peer - 0x0(EMPTY), combined - 0x0(EMPTY) Jun 14 10:24:21 VERBOSE[4101]: Found peer 'hschurig' Jun 14 10:24:21 DEBUG[4101]: Setting NAT on RTP to 0 Jun 14 10:24:21 DEBUG[4101]: Check for res for hschurig Jun 14 10:24:21 DEBUG[4101]: hschurig is not a local user Jun 14 10:24:21 VERBOSE[4101]: Looking for 89958 in default Jun 14 10:24:21 DEBUG[4101]: build_route: Contact hop: Jun 14 10:24:21 VERBOSE[4101]: list_route: hop: Jun 14 10:24:21 VERBOSE[4101]: Transmitting (no NAT): SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.233.67;branch=z9hG4bK7dfefb472500b0b8 From: "Holger Schurig" ;tag=8ceda10af2df82b9 To: ;tag=as64e878ab Call-ID: a8f9fd1d2aee1e1f@192.168.233.67 CSeq: 44566 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER Contact: Content-Length: 0 to 192.168.233.67:5060 Jun 14 10:24:21 DEBUG[8199]: Launching 'SetCIDNum' Jun 14 10:24:21 DEBUG[8199]: Launching 'SetCIDName' Jun 14 10:24:21 DEBUG[8199]: Launching 'Dial' Jun 14 10:24:21 DEBUG[8199]: SIMPLE DIAL (NO URL) Jun 14 10:24:21 DEBUG[8199]: New max nontrunk callno is 5 Jun 14 10:24:21 DEBUG[8199]: Creating new call structure 4 Jun 14 10:24:21 VERBOSE[8199]: -- Called 254041:popo12@iax2.fwdnet.net/958 Jun 14 10:24:21 VERBOSE[8199]: Transmitting (no NAT): SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.233.67;branch=z9hG4bK7dfefb472500b0b8 From: "Holger Schurig" ;tag=8ceda10af2df82b9 To: ;tag=as64e878ab Call-ID: a8f9fd1d2aee1e1f@192.168.233.67 CSeq: 44566 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER Contact: Content-Length: 0 to 192.168.233.67:5060 Jun 14 10:24:21 DEBUG[5126]: Sending 13 on 4/0 to 65.39.205.121:4569 Jun 14 10:24:21 DEBUG[5126]: Received packet 0, (6, 8) Jun 14 10:24:21 DEBUG[5126]: Cancelling transmission of packet 0 Jun 14 10:24:21 DEBUG[5126]: IAX subclass 8 received Jun 14 10:24:21 DEBUG[5126]: min = 0, max = 0, jb = 0, lateness = -10 Jun 14 10:24:21 DEBUG[5126]: Sending 165 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:21 DEBUG[5126]: Raw Hangup 65.39.205.121:4569, src=2, dst=32 Jun 14 10:24:21 DEBUG[5126]: Received packet 1, (6, 7) Jun 14 10:24:21 DEBUG[5126]: Cancelling transmission of packet 1 Jun 14 10:24:21 DEBUG[5126]: IAX subclass 7 received Jun 14 10:24:21 DEBUG[5126]: min = 0, max = 0, jb = 0, lateness = -1 Jun 14 10:24:21 VERBOSE[5126]: -- Call accepted by 65.39.205.121 (format ULAW) Jun 14 10:24:21 VERBOSE[5126]: -- Format for call is ULAW Jun 14 10:24:21 DEBUG[5126]: Sending 156 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:21 DEBUG[5126]: Received packet 2, (4, -1) Jun 14 10:24:21 DEBUG[5126]: Sending 159 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:21 DEBUG[5126]: min = 0, max = 0, jb = 0, lateness = 16 Jun 14 10:24:21 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:21 DEBUG[5126]: Received packet 3, (4, 3) Jun 14 10:24:21 DEBUG[5126]: Sending 162 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:21 DEBUG[5126]: min = 0, max = 0, jb = 0, lateness = 56 Jun 14 10:24:21 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:21 VERBOSE[8199]: -- IAX2[65.39.205.121:4569]/4 is ringing Jun 14 10:24:22 DEBUG[5126]: Raw Hangup 65.39.205.121:4569, src=3, dst=229 Jun 14 10:24:24 DEBUG[5126]: Received packet 4, (4, -1) Jun 14 10:24:24 DEBUG[5126]: Sending 3245 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:24 DEBUG[5126]: min = 0, max = 0, jb = 0, lateness = -12 Jun 14 10:24:24 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:24 DEBUG[5126]: Received packet 5, (4, 4) Jun 14 10:24:24 DEBUG[5126]: Sending 3248 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:24 DEBUG[5126]: min = 0, max = 0, jb = 0, lateness = -14 Jun 14 10:24:24 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:24 VERBOSE[8199]: -- IAX2[65.39.205.121:4569]/4 answered SIP/hschurig-256d Jun 14 10:24:24 DEBUG[8199]: Set channel SIP/hschurig-256d to read format ULAW Jun 14 10:24:24 DEBUG[8199]: Set channel IAX2[65.39.205.121:4569]/4 to write format ULAW Jun 14 10:24:24 DEBUG[8199]: Set channel SIP/hschurig-256d to write format ALAW Jun 14 10:24:24 DEBUG[8199]: Set channel IAX2[65.39.205.121:4569]/4 to read format ALAW Jun 14 10:24:24 DEBUG[8199]: sip_answer(SIP/hschurig-256d) Jun 14 10:24:24 VERBOSE[8199]: We're at 192.168.233.66 port 16118 Jun 14 10:24:24 VERBOSE[8199]: Answering with preferred capability 0x8(ALAW) Jun 14 10:24:24 VERBOSE[8199]: Answering with preferred capability 0x4(ULAW) Jun 14 10:24:24 VERBOSE[8199]: Answering with preferred capability 0x400(ILBC) Jun 14 10:24:24 VERBOSE[8199]: Reliably Transmitting (no NAT): SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.233.67;branch=z9hG4bK7dfefb472500b0b8 From: "Holger Schurig" ;tag=8ceda10af2df82b9 To: ;tag=as64e878ab Call-ID: a8f9fd1d2aee1e1f@192.168.233.67 CSeq: 44566 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER Contact: Content-Type: application/sdp Content-Length: 212 v=0 o=root 5595 5595 IN IP4 192.168.233.66 s=session c=IN IP4 192.168.233.66 t=0 0 m=audio 16118 RTP/AVP 8 0 97 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:97 iLBC/8000 a=silenceSupp:off - - - - to 192.168.233.67:5060 Jun 14 10:24:24 DEBUG[5126]: Received packet 6, (2, 4) Jun 14 10:24:24 DEBUG[5126]: Ooh, voice format changed to 4 Jun 14 10:24:24 DEBUG[5126]: Set channel IAX2[65.39.205.121:4569]/4 to read format ALAW Jun 14 10:24:24 DEBUG[5126]: Sending 3240 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:24 DEBUG[5126]: Received out of order packet... (type=2, subclass 4, ts = 3240, last = 3248) Jun 14 10:24:24 DEBUG[5126]: min = -3, max = 0, jb = 0, lateness = -3 Jun 14 10:24:24 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:24 DEBUG[8199]: Ooh, format changed from UNKN to ALAW Jun 14 10:24:24 VERBOSE[4101]: Sip read: ACK sip:89958@192.168.233.66:0 SIP/2.0 Via: SIP/2.0/UDP 192.168.233.67;branch=z9hG4bK7dfefb472500b0b8 From: "Holger Schurig" ;tag=8ceda10af2df82b9 To: ;tag=as64e878ab Contact: Call-ID: a8f9fd1d2aee1e1f@192.168.233.67 CSeq: 44566 ACK User-Agent: Grandstream BT100 1.0.5.0 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Content-Type: application/sdp Content-Length: 151 v=0 o=hschurig 8000 8000 IN IP4 192.168.233.67 s=SIP Call c=IN IP4 192.168.233.67 t=0 0 m=audio 5004 RTP/AVP 8 a=rtpmap:8 PCMA/8000 a=ptime:20 Jun 14 10:24:24 VERBOSE[4101]: 12 headers, 8 lines Jun 14 10:24:24 DEBUG[4101]: Stopping retransmission on 'a8f9fd1d2aee1e1f@192.168.233.67' of Response 44566: Found Jun 14 10:24:24 VERBOSE[4101]: Found RTP audio format 8 Jun 14 10:24:24 VERBOSE[4101]: Peer RTP is at port 192.168.233.67:0 Jun 14 10:24:24 VERBOSE[4101]: Found description format PCMA Jun 14 10:24:24 VERBOSE[4101]: Capabilities: us - 0x40c(ULAW|ALAW|ILBC), peer - audio=0x8(ALAW)/video=0x0(EMPTY), combined - 0x8(ALAW) Jun 14 10:24:24 VERBOSE[4101]: Non-codec capabilities: us - 0x1(G723), peer - 0x0(EMPTY), combined - 0x0(EMPTY) Jun 14 10:24:24 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -5 Jun 14 10:24:24 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:24 DEBUG[5126]: Sending 3416 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:24 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -3 Jun 14 10:24:24 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:24 DEBUG[8199]: Sending 3436 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:24 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -5 Jun 14 10:24:24 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:24 DEBUG[8199]: Sending 3456 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:24 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -4 Jun 14 10:24:24 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:24 DEBUG[8199]: Sending 3476 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:24 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -5 Jun 14 10:24:24 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:24 DEBUG[8199]: Sending 3496 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -3 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 3516 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -4 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 3536 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -3 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 3556 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: Received packet 7, (6, 4) Jun 14 10:24:25 DEBUG[5126]: Cancelling transmission of packet 2 Jun 14 10:24:25 DEBUG[5126]: IAX subclass 4 received Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -3 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -4 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 3576 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -3 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 3596 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -3 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 3616 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -4 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 3636 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -3 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 3656 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -4 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 3676 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -3 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 3696 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -2 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 3716 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -4 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 3736 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -4 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 3756 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -3 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 3776 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -3 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 3796 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -4 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 3816 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -3 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 3836 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -4 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 3856 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -3 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 3876 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -3 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 3896 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -4 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 3916 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -3 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 3936 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -4 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 3956 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -3 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 3976 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -4 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 3996 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -3 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 4016 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -4 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 4036 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -2 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 4056 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -4 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 4076 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -3 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 4096 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -4 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 4116 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -3 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 4136 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -4 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 4156 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -4 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 4176 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -5 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 4196 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -4 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 4216 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -5 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 4236 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -4 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 4256 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -5 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 4276 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -3 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 4296 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -5 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 4316 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -4 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 4336 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -5 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 4356 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -4 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 4376 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -4 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 4396 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -5 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 4416 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -4 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 4436 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -5 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 4456 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -4 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 4476 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:25 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -5 Jun 14 10:24:25 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:25 DEBUG[8199]: Sending 4496 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -3 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 4516 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -4 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 4536 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -3 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 4556 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -4 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 4576 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -3 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 4596 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -4 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 4616 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = -3 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 4636 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[8199]: Sending 4656 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[8199]: Sending 4676 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = 29 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 4696 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = 35 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 4716 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 0, jb = 0, lateness = 32 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 4736 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 29, jb = 29, lateness = 33 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 4756 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 32, jb = 32, lateness = 33 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 4776 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 32, jb = 32, lateness = 32 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 4796 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 33, jb = 33, lateness = 33 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 4816 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 33, jb = 33, lateness = 32 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 4836 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 33, jb = 33, lateness = 32 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 4856 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 33, jb = 33, lateness = 34 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 4876 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 33, jb = 33, lateness = 32 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 4896 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 33, jb = 33, lateness = 33 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 4916 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 33, jb = 33, lateness = 33 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 4936 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 33, jb = 33, lateness = 33 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 4956 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 33, jb = 33, lateness = 33 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 4976 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 33, jb = 33, lateness = 33 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 4996 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 33, jb = 33, lateness = 33 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 5016 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 33, jb = 33, lateness = 32 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 5036 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 33, jb = 33, lateness = 32 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 5056 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 33, jb = 33, lateness = 32 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 5076 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 33, jb = 33, lateness = 34 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 5096 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 33, jb = 33, lateness = 32 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 5116 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 34, jb = 34, lateness = 34 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 5136 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 34, jb = 34, lateness = 32 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 5156 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 34, jb = 34, lateness = 33 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 5176 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 34, jb = 34, lateness = 30 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 5196 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 34, jb = 34, lateness = 33 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 5216 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 34, jb = 34, lateness = 31 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 5236 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 34, jb = 34, lateness = 32 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 5256 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 34, jb = 34, lateness = 32 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 5276 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 34, jb = 34, lateness = 33 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 5296 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 34, jb = 34, lateness = 33 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 5316 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 34, jb = 34, lateness = 36 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 5336 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 34, jb = 34, lateness = 32 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 5356 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 34, jb = 34, lateness = 36 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 5376 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 34, jb = 34, lateness = 32 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 5396 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 35, jb = 35, lateness = 36 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 5416 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 35, jb = 35, lateness = 32 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 5436 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 36, jb = 36, lateness = 36 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 5456 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 36, jb = 36, lateness = 35 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 5476 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 36, jb = 36, lateness = 36 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:26 DEBUG[8199]: Sending 5496 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:26 DEBUG[5126]: min = -5, max = 36, jb = 36, lateness = 31 Jun 14 10:24:26 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 5516 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 36, jb = 36, lateness = 35 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 5536 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 36, jb = 36, lateness = 37 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 5556 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 36, jb = 36, lateness = 33 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 5576 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 36, jb = 36, lateness = 37 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 5596 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 36, jb = 36, lateness = 33 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 5616 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 36, jb = 36, lateness = 37 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 5636 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 36, jb = 36, lateness = 33 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 5656 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 37 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 5676 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 32 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 5696 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 37 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 5716 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 32 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 5736 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 36 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 5756 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 36 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 5776 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 34 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 5796 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 36 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 5816 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 34 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 5836 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 36 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 5856 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 34 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 5876 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 36 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 5896 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 33 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 5916 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 37 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 5936 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 32 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 5956 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 35 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 5976 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 32 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 5996 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 35 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 6016 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 36 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 6036 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 33 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 6056 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 36 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 6076 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 33 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 6096 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 37 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 6116 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 34 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 6136 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 35 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 6156 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 32 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 6176 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 32 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 6196 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 32 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 6216 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 33 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 6236 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 36 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 6256 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 32 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 6276 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 36 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 6296 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 31 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 6316 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 36 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 6336 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 32 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 6356 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 36 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 6376 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 35 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 6396 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 33 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 6416 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 35 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 6436 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 34 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 6456 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 35 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 6476 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:27 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 36 Jun 14 10:24:27 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:27 DEBUG[8199]: Sending 6496 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = -5, max = 37, jb = 37, lateness = 36 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 6516 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = -4, max = 37, jb = 37, lateness = 37 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 6536 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = -4, max = 37, jb = 37, lateness = 36 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 6556 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = -4, max = 37, jb = 37, lateness = 37 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 6576 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = -4, max = 37, jb = 37, lateness = 36 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 6596 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = -4, max = 37, jb = 37, lateness = 37 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 6616 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = -4, max = 37, jb = 37, lateness = 37 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 6636 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = -3, max = 37, jb = 37, lateness = 36 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 6656 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 29, max = 37, jb = 37, lateness = 36 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 6676 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 30, max = 37, jb = 37, lateness = 37 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 6696 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 30, max = 37, jb = 37, lateness = 37 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 6716 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 30, max = 37, jb = 37, lateness = 36 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 6736 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 30, max = 37, jb = 37, lateness = 37 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 6756 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 30, max = 37, jb = 37, lateness = 36 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 6776 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 30, max = 37, jb = 37, lateness = 37 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 6796 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 30, max = 37, jb = 37, lateness = 37 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 6816 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 30, max = 37, jb = 37, lateness = 36 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 6836 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 30, max = 37, jb = 37, lateness = 37 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 6856 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 30, max = 37, jb = 37, lateness = 36 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 6876 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 30, max = 37, jb = 37, lateness = 36 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 6896 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 30, max = 37, jb = 37, lateness = 37 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 6916 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 30, max = 37, jb = 37, lateness = 37 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 6936 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 30, max = 37, jb = 37, lateness = 36 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 6956 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 30, max = 37, jb = 37, lateness = 37 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 6976 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 30, max = 37, jb = 37, lateness = 37 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 6996 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 30, max = 37, jb = 37, lateness = 37 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 7016 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 30, max = 37, jb = 37, lateness = 36 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 7036 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 30, max = 37, jb = 37, lateness = 37 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 7056 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 30, max = 37, jb = 37, lateness = 37 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 7076 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 30, max = 37, jb = 37, lateness = 36 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 7096 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 30, max = 37, jb = 37, lateness = 37 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 7116 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 30, max = 37, jb = 37, lateness = 36 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 7136 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 30, max = 37, jb = 37, lateness = 37 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 7156 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 30, max = 37, jb = 37, lateness = 35 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 7176 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 36 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 7196 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 35 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 7216 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 36 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 7236 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 36 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 7256 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 35 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 7276 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 36 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 7296 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 35 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 7316 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 36 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 7336 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 35 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 7356 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 36 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 7376 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 35 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 7396 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 36 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 7416 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 35 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 7436 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 36 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 7456 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 36 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 7476 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:28 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 35 Jun 14 10:24:28 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:28 DEBUG[8199]: Sending 7496 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 37 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 7516 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 36 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 7536 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 38 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 7556 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 36 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 7576 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 36 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 7596 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 37 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 7616 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 37 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 7636 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 36 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 7656 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 37 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 7676 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 36 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 7696 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 37 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 7716 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 36 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 7736 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 37 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 7756 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 37 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 7776 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 36 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 7796 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 37 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 7816 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 36 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 7836 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 36 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 7856 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 37 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 7876 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 36 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 7896 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 38 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 7916 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 37 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 7936 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 36 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 7956 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 37 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 7976 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 37 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 7996 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 36 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 8016 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 37 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 8036 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 37 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 8056 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 36 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 8076 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 36 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 8096 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 36 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 8116 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 37 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 8136 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 36 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 8156 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 36 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 8176 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 35 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 8196 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 36 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 8216 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 35 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 8236 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 36 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 8256 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 35 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 8276 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 31, max = 37, jb = 37, lateness = 36 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 8296 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 32, max = 37, jb = 37, lateness = 35 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 8316 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 32, max = 37, jb = 37, lateness = 35 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 8336 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 33, max = 37, jb = 37, lateness = 36 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 8356 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 33, max = 37, jb = 37, lateness = 35 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 8376 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 33, max = 37, jb = 37, lateness = 36 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 8396 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 34, max = 37, jb = 37, lateness = 35 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 8416 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 34, max = 37, jb = 37, lateness = 36 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 8436 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 35, max = 37, jb = 37, lateness = 35 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 8456 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[5126]: min = 35, max = 37, jb = 37, lateness = 36 Jun 14 10:24:29 DEBUG[5126]: Calculated ms is 0 Jun 14 10:24:29 DEBUG[8199]: Sending 8476 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:29 DEBUG[8199]: Sending 8496 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:30 DEBUG[8199]: Sending 8516 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:30 DEBUG[5126]: Received packet 7, (6, 5) Jun 14 10:24:30 DEBUG[5126]: IAX subclass 5 received Jun 14 10:24:30 DEBUG[5126]: min = 35, max = 37, jb = 37, lateness = -11 Jun 14 10:24:30 DEBUG[5126]: Immediately destroying 4, having received hangup Jun 14 10:24:30 DEBUG[5126]: Sending 8379 on 4/36 to 65.39.205.121:4569 Jun 14 10:24:30 DEBUG[8199]: Didn't get a frame from channel: IAX2[65.39.205.121:4569]/4 Jun 14 10:24:30 DEBUG[8199]: Bridge stops bridging channels SIP/hschurig-256d and IAX2[65.39.205.121:4569]/4 Jun 14 10:24:30 DEBUG[8199]: Hanging up channel 'IAX2[65.39.205.121:4569]/4' Jun 14 10:24:30 DEBUG[8199]: We're hanging up IAX2[65.39.205.121:4569]/4 now... Jun 14 10:24:30 DEBUG[8199]: Really destroying IAX2[65.39.205.121:4569]/4 now... Jun 14 10:24:30 VERBOSE[8199]: -- Hungup 'IAX2[65.39.205.121:4569]/4' Jun 14 10:24:30 DEBUG[8199]: Spawn extension (default,89958,3) exited non-zero on 'SIP/hschurig-256d' Jun 14 10:24:30 DEBUG[8199]: Hanging up channel 'SIP/hschurig-256d' Jun 14 10:24:30 DEBUG[8199]: sip_hangup(SIP/hschurig-256d) Jun 14 10:24:30 DEBUG[8199]: update_user_counter(hschurig) - decrement inUse counter Jun 14 10:24:30 DEBUG[8199]: hschurig is not a local user Jun 14 10:24:30 VERBOSE[8199]: set_destination: Parsing for address/port to send to Jun 14 10:24:30 VERBOSE[8199]: set_destination: set destination to 192.168.233.67, port 5060 Jun 14 10:24:30 VERBOSE[8199]: Reliably Transmitting: BYE sip:hschurig@192.168.233.67 SIP/2.0 Via: SIP/2.0/UDP 192.168.233.66:0;branch=z9hG4bK79e9c75b From: ;tag=as64e878ab To: "Holger Schurig" ;tag=8ceda10af2df82b9 Contact: Call-ID: a8f9fd1d2aee1e1f@192.168.233.67 CSeq: 102 BYE User-Agent: Asterisk PBX Content-Length: 0 (no NAT) to 192.168.233.67:5060 Jun 14 10:24:30 VERBOSE[4101]: Sip read: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.233.66:0;branch=z9hG4bK79e9c75b From: ;tag=as64e878ab To: "Holger Schurig" ;tag=8ceda10af2df82b9 Call-ID: a8f9fd1d2aee1e1f@192.168.233.67 CSeq: 102 BYE User-Agent: Grandstream BT100 1.0.5.0 Contact: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Content-Length: 0 Jun 14 10:24:30 VERBOSE[4101]: 10 headers, 0 lines Jun 14 10:24:30 DEBUG[4101]: Stopping retransmission on 'a8f9fd1d2aee1e1f@192.168.233.67' of Request 102: Found Jun 14 10:24:30 VERBOSE[4101]: Message is BYE Jun 14 10:24:30 VERBOSE[4101]: Destroying call 'a8f9fd1d2aee1e1f@192.168.233.67' Jun 14 10:24:35 VERBOSE[1024]: Beginning asterisk shutdown.... Jun 14 10:24:35 VERBOSE[1024]: Executing last minute cleanups Jun 14 10:24:35 VERBOSE[1024]: == Destroying any remaining musiconhold processes Jun 14 10:24:35 VERBOSE[1024]: Asterisk cleanly ending (0).