voip01*CLI> voip01*CLI> core set verbose 9 Verbosity was 5 and is now 9 voip01*CLI> core set debug 4 Core debug was 5 and is now 4 voip01*CLI> logger reload Asterisk Event Logger restarted Asterisk Queue Logger restarted voip01*CLI> sip set debug on SIP Debugging enabled oip01*CLI> <--- SIP read from UDP://:1025 ---> PUBLISH sip:@ SIP/2.0 Via: SIP/2.0/UDP :1026;branch=z9hG4bK-8mbo5iqc8vu9;rport From: "041 V2" @>;tag=yuf05o99vf To: "041 V2" @> Call-ID: 3c2675e9975e-5i1kib54izwy@snom190 CSeq: 1 PUBLISH Max-Forwards: 70 Event: proxy-config Content-Type: application/text Content-Length: 0 <-------------> [Jun 25 14:16:24] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 0 [ 49]: PUBLISH sip:@ SIP/2.0 [Jun 25 14:16:24] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 1 [ 69]: Via: SIP/2.0/UDP :1026;branch=z9hG4bK-8mbo5iqc8vu9;rport [Jun 25 14:16:24] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 2 [ 65]: From: "041 V2" <@>;tag=yuf05o99vf [Jun 25 14:16:24] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 3 [ 48]: To: "041 V2" @> [Jun 25 14:16:24] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 4 [ 42]: Call-ID: 3c2675e9975e-5i1kib54izwy@snom190 [Jun 25 14:16:24] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 5 [ 15]: CSeq: 1 PUBLISH [Jun 25 14:16:24] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Jun 25 14:16:24] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 7 [ 19]: Event: proxy-config [Jun 25 14:16:24] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 8 [ 30]: Content-Type: application/text [Jun 25 14:16:24] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 9 [ 17]: Content-Length: 0 [Jun 25 14:16:24] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 10 [ 0]: --- (10 headers 0 lines) --- [Jun 25 14:16:24] DEBUG[76060]: acl.c:490 ast_ouraddrfor: Found IP address for this socket <--- Transmitting (no NAT) to :1025 ---> SIP/2.0 501 Method Not Implemented Via: SIP/2.0/UDP :1026;branch=z9hG4bK-8mbo5iqc8vu9;received=;rport=1025 From: "041 V2" @>;tag=yuf05o99vf To: "041 V2" @>;tag=as544e5e4e Call-ID: 3c2675e9975e-5i1kib54izwy@snom190 CSeq: 1 PUBLISH User-Agent: Asterisk PBX 1.6.0-beta9 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Content-Length: 0 <------------> [Jun 25 14:16:24] DEBUG[76060]: chan_sip.c:2521 __sip_xmit: Trying to put 'SIP/2.0 50' onto UDP socket... [Jun 25 14:16:24] DEBUG[76060]: chan_sip.c:5959 find_call: Got a request with unsupported SIP method. [Jun 25 14:16:24] DEBUG[76060]: chan_sip.c:18102 handle_request_do: Invalid SIP message - rejected , no callid, len 392 oip01*CLI> <--- SIP read from UDP://:1025 ---> PUBLISH sip:@ SIP/2.0 Via: SIP/2.0/UDP :1026;branch=z9hG4bK-ub6k8ez28ijc;rport From: "041 V2" @>;tag=wwl6mx12qx To: "041 V2" @> Call-ID: 3c2675ea1d4c-zx441mni59ks@snom190 CSeq: 1 PUBLISH Max-Forwards: 70 Event: number-guessing Content-Type: application/text Content-Length: 25 Number: 13 Max-Hits: 3 <-------------> [Jun 25 14:16:24] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 0 [ 49]: PUBLISH sip:@ SIP/2.0 [Jun 25 14:16:24] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 1 [ 69]: Via: SIP/2.0/UDP :1026;branch=z9hG4bK-ub6k8ez28ijc;rport [Jun 25 14:16:24] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 2 [ 65]: From: "041 V2" @>;tag=wwl6mx12qx [Jun 25 14:16:24] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 3 [ 48]: To: "041 V2" @> [Jun 25 14:16:24] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 4 [ 42]: Call-ID: 3c2675ea1d4c-zx441mni59ks@snom190 [Jun 25 14:16:24] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 5 [ 15]: CSeq: 1 PUBLISH [Jun 25 14:16:24] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Jun 25 14:16:24] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 7 [ 22]: Event: number-guessing [Jun 25 14:16:24] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 8 [ 30]: Content-Type: application/text [Jun 25 14:16:24] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 9 [ 18]: Content-Length: 25 [Jun 25 14:16:24] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 10 [ 0]: [Jun 25 14:16:24] DEBUG[76060]: chan_sip.c:6142 parse_request: Body 0 [ 10]: Number: 13 [Jun 25 14:16:24] DEBUG[76060]: chan_sip.c:6142 parse_request: Body 1 [ 11]: Max-Hits: 3 --- (10 headers 2 lines) --- [Jun 25 14:16:24] DEBUG[76060]: acl.c:490 ast_ouraddrfor: Found IP address for this socket <--- Transmitting (no NAT) to :1025 ---> SIP/2.0 501 Method Not Implemented Via: SIP/2.0/UDP :1026;branch=z9hG4bK-ub6k8ez28ijc;received=;rport=1025 From: "041 V2" @>;tag=wwl6mx12qx To: "041 V2" @>;tag=as427a9551 Call-ID: 3c2675ea1d4c-zx441mni59ks@snom190 CSeq: 1 PUBLISH User-Agent: Asterisk PBX 1.6.0-beta9 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Content-Length: 0 <------------> [Jun 25 14:16:24] DEBUG[76060]: chan_sip.c:2521 __sip_xmit: Trying to put 'SIP/2.0 50' onto UDP socket... [Jun 25 14:16:24] DEBUG[76060]: chan_sip.c:5959 find_call: Got a request with unsupported SIP method. [Jun 25 14:16:24] DEBUG[76060]: chan_sip.c:18102 handle_request_do: Invalid SIP message - rejected , no callid, len 421 oip01*CLI> <--- SIP read from UDP://:1025 ---> PUBLISH sip:@ SIP/2.0 Via: SIP/2.0/UDP :1026;branch=z9hG4bK-9sjserbynhn6;rport From: "041 V2" @>;tag=dzqeixqx8s To: "041 V2" @> Call-ID: 3c2675ecb239-m5jtnom70bpx@snom190 CSeq: 1 PUBLISH Max-Forwards: 70 Event: proxy-config Content-Type: application/text Content-Length: 0 <-------------> [Jun 25 14:16:27] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 0 [ 49]: PUBLISH sip:@ SIP/2.0 [Jun 25 14:16:27] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 1 [ 69]: Via: SIP/2.0/UDP :1026;branch=z9hG4bK-9sjserbynhn6;rport [Jun 25 14:16:27] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 2 [ 65]: From: "041 V2" @>;tag=dzqeixqx8s [Jun 25 14:16:27] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 3 [ 48]: To: "041 V2" @> [Jun 25 14:16:27] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 4 [ 42]: Call-ID: 3c2675ecb239-m5jtnom70bpx@snom190 [Jun 25 14:16:27] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 5 [ 15]: CSeq: 1 PUBLISH [Jun 25 14:16:27] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Jun 25 14:16:27] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 7 [ 19]: Event: proxy-config [Jun 25 14:16:27] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 8 [ 30]: Content-Type: application/text [Jun 25 14:16:27] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 9 [ 17]: Content-Length: 0 [Jun 25 14:16:27] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 10 [ 0]: --- (10 headers 0 lines) --- [Jun 25 14:16:27] DEBUG[76060]: acl.c:490 ast_ouraddrfor: Found IP address for this socket <--- Transmitting (no NAT) to :1025 ---> SIP/2.0 501 Method Not Implemented Via: SIP/2.0/UDP :1026;branch=z9hG4bK-9sjserbynhn6;received=;rport=1025 From: "041 V2" @>;tag=dzqeixqx8s To: "041 V2" @>;tag=as2d820f9e Call-ID: 3c2675ecb239-m5jtnom70bpx@snom190 CSeq: 1 PUBLISH User-Agent: Asterisk PBX 1.6.0-beta9 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Content-Length: 0 <------------> [Jun 25 14:16:27] DEBUG[76060]: chan_sip.c:2521 __sip_xmit: Trying to put 'SIP/2.0 50' onto UDP socket... [Jun 25 14:16:27] DEBUG[76060]: chan_sip.c:5959 find_call: Got a request with unsupported SIP method. [Jun 25 14:16:27] DEBUG[76060]: chan_sip.c:18102 handle_request_do: Invalid SIP message - rejected , no callid, len 392 [Jun 25 14:16:27] DEBUG[76060]: cdr.c:1130 ast_cdr_submit_batch: CDR multi-threaded batch processing begins now [Jun 25 14:16:27] DEBUG[76060]: cdr.c:1230 do_cdr: Processed 1 scheduled CDR batches from the run queue [Jun 25 14:16:27] DEBUG[76060]: cdr_pgsql.c:270 pgsql_log: cdr_pgsql: inserting a CDR record. oip01*CLI> <--- SIP read from UDP://:1025 ---> PUBLISH sip:@ SIP/2.0 Via: SIP/2.0/UDP :1026;branch=z9hG4bK-yxa9vxaiolc2;rport From: "041 V2" @>;tag=hxz78n0t3r To: "041 V2" @> Call-ID: 3c2675ed3827-baex1ftaw6ee@snom190 CSeq: 1 PUBLISH Max-Forwards: 70 Event: number-guessing Content-Type: application/text Content-Length: 27 Number: 1322 Max-Hits: 3 <-------------> [Jun 25 14:16:27] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 0 [ 49]: PUBLISH sip:@ SIP/2.0 [Jun 25 14:16:27] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 1 [ 69]: Via: SIP/2.0/UDP :1026;branch=z9hG4bK-yxa9vxaiolc2;rport [Jun 25 14:16:27] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 2 [ 65]: From: "041 V2" @>;tag=hxz78n0t3r [Jun 25 14:16:27] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 3 [ 48]: To: "041 V2" @> [Jun 25 14:16:27] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 4 [ 42]: Call-ID: 3c2675ed3827-baex1ftaw6ee@snom190 [Jun 25 14:16:27] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 5 [ 15]: CSeq: 1 PUBLISH [Jun 25 14:16:27] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Jun 25 14:16:27] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 7 [ 22]: Event: number-guessing [Jun 25 14:16:27] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 8 [ 30]: Content-Type: application/text [Jun 25 14:16:27] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 9 [ 18]: Content-Length: 27 [Jun 25 14:16:27] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 10 [ 0]: [Jun 25 14:16:27] DEBUG[76060]: chan_sip.c:6142 parse_request: Body 0 [ 12]: Number: 1322 [Jun 25 14:16:27] DEBUG[76060]: chan_sip.c:6142 parse_request: Body 1 [ 11]: Max-Hits: 3 --- (10 headers 2 lines) --- [Jun 25 14:16:27] DEBUG[76060]: acl.c:490 ast_ouraddrfor: Found IP address for this socket <--- Transmitting (no NAT) to :1025 ---> SIP/2.0 501 Method Not Implemented Via: SIP/2.0/UDP :1026;branch=z9hG4bK-yxa9vxaiolc2;received=;rport=1025 From: "041 V2" @>;tag=hxz78n0t3r To: "041 V2" @>;tag=as2e9ef243 Call-ID: 3c2675ed3827-baex1ftaw6ee@snom190 CSeq: 1 PUBLISH User-Agent: Asterisk PBX 1.6.0-beta9 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Content-Length: 0 <------------> [Jun 25 14:16:27] DEBUG[76060]: chan_sip.c:2521 __sip_xmit: Trying to put 'SIP/2.0 50' onto UDP socket... [Jun 25 14:16:27] DEBUG[76060]: chan_sip.c:5959 find_call: Got a request with unsupported SIP method. [Jun 25 14:16:27] DEBUG[76060]: chan_sip.c:18102 handle_request_do: Invalid SIP message - rejected , no callid, len 423 oip01*CLI> <--- SIP read from UDP://:1025 ---> INVITE sip:@;user=phone SIP/2.0 Via: SIP/2.0/UDP :1026;branch=z9hG4bK-729i5hn1kqz5;rport From: "041 V2" @>;tag=7z278leqz4 To: @;user=phone> Call-ID: 3c2675ef6b6c-3y1w8ym6c3ez@snom190 CSeq: 1 INVITE Max-Forwards: 70 Contact: @:1026;line=yqw97773> P-Key-Flags: keys="3" User-Agent: snom190/3.60x Accept: application/sdp Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer Supported: timer, 100rel, replaces Session-Expires: 3600 Content-Type: application/sdp Content-Length: 370 <-------------> [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 0 [ 50]: INVITE sip:@;user=phone SIP/2.0 [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 1 [ 69]: Via: SIP/2.0/UDP :1026;branch=z9hG4bK-729i5hn1kqz5;rport [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 2 [ 65]: From: "041 V2" <@>;tag=7z278leqz4 [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 3 [ 41]: To: @;user=phone> [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 4 [ 42]: Call-ID: 3c2675ef6b6c-3y1w8ym6c3ez@snom190 [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 5 [ 14]: CSeq: 1 INVITE [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 7 [ 63]: Contact: <@:1026;line=yqw97773> [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 8 [ 21]: P-Key-Flags: keys="3" [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 9 [ 25]: User-Agent: snom190/3.60x [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 10 [ 23]: Accept: application/sdp [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 11 [ 88]: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 12 [ 31]: Allow-Events: talk, hold, refer [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 13 [ 34]: Supported: timer, 100rel, replaces [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 14 [ 21]: Session-Expires: 3600 [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 15 [ 29]: Content-Type: application/sdp [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 16 [ 19]: Content-Length: 370 [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 17 [ 0]: --- (17 headers 0 lines) --- [Jun 25 14:16:30] DEBUG[76060]: acl.c:490 ast_ouraddrfor: Found IP address for this socket [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:3838 do_setnat: Setting NAT on RTP to Off [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:3846 do_setnat: Setting NAT on UDPTL to Off [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:5831 sip_alloc: Allocating new SIP dialog for 3c2675ef6b6c-3y1w8ym6c3ez@snom190 - INVITE (With RTP) [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:17896 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:2421 parse_sip_options: Begin: parsing SIP "Supported: timer, 100rel, replaces" [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:2429 parse_sip_options: Found SIP option: -timer- [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:2435 parse_sip_options: Matched SIP option: timer [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:2429 parse_sip_options: Found SIP option: -100rel- [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:2435 parse_sip_options: Matched SIP option: 100rel [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:2429 parse_sip_options: Found SIP option: -replaces- [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:2435 parse_sip_options: Matched SIP option: replaces Sending to : 1025 (NAT) [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:16314 handle_request_invite: Initializing initreq for method INVITE - callid 3c2675ef6b6c-3y1w8ym6c3ez@snom190 Using INVITE request as basis request - 3c2675ef6b6c-3y1w8ym6c3ez@snom190 Found user '' for '' [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:3838 do_setnat: Setting NAT on RTP to On [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:3846 do_setnat: Setting NAT on UDPTL to On <--- Reliably Transmitting (NAT) to :1025 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP :1026;branch=z9hG4bK-729i5hn1kqz5;received=;rport=1025 From: "041 V2" @>;tag=7z278leqz4 To: @;user=phone>;tag=as7eff1192 Call-ID: 3c2675ef6b6c-3y1w8ym6c3ez@snom190 CSeq: 1 INVITE User-Agent: Asterisk PBX 1.6.0-beta9 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="server.realm", nonce="4fc82296" Content-Length: 0 <------------> [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:2838 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #9 [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:2521 __sip_xmit: Trying to put 'SIP/2.0 40' onto UDP socket... Scheduling destruction of SIP dialog '3c2675ef6b6c-3y1w8ym6c3ez@snom190' in 32000 ms (Method: INVITE) [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:3763 sip_destroy_user: Destroying user object from memory: oip01*CLI> <--- SIP read from UDP://:1025 ---> ACK sip:@;user=phone SIP/2.0 Via: SIP/2.0/UDP :1026;branch=z9hG4bK-729i5hn1kqz5;rport From: "041 V2" @>;tag=7z278leqz4 To: @;user=phone>;tag=as7eff1192 Call-ID: 3c2675ef6b6c-3y1w8ym6c3ez@snom190 CSeq: 1 ACK Max-Forwards: 70 Contact: @:1026;line=yqw97773> Content-Length: 0 <-------------> [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 0 [ 47]: ACK sip:@;user=phone SIP/2.0 [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 1 [ 69]: Via: SIP/2.0/UDP :1026;branch=z9hG4bK-729i5hn1kqz5;rport [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 2 [ 65]: From: "041 V2" <@>;tag=7z278leqz4 [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 3 [ 56]: To: @;user=phone>;tag=as7eff1192 [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 4 [ 42]: Call-ID: 3c2675ef6b6c-3y1w8ym6c3ez@snom190 [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 5 [ 11]: CSeq: 1 ACK [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 7 [ 63]: Contact: <@:1026;line=yqw97773> [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 8 [ 17]: Content-Length: 0 [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 9 [ 0]: --- (9 headers 0 lines) --- [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:17896 handle_incoming: **** Received ACK (6) - Command in SIP ACK [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:2967 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #9 [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:2997 __sip_ack: Stopping retransmission on '3c2675ef6b6c-3y1w8ym6c3ez@snom190' of Response 1: Match Found oip01*CLI> <--- SIP read from UDP://:1025 ---> INVITE sip:@;user=phone SIP/2.0 Via: SIP/2.0/UDP :1026;branch=z9hG4bK-6s3di0ghzfsq;rport From: "041 V2" @>;tag=7z278leqz4 To: @;user=phone> Call-ID: 3c2675ef6b6c-3y1w8ym6c3ez@snom190 CSeq: 2 INVITE Max-Forwards: 70 Contact: @:1026;line=yqw97773> P-Key-Flags: keys="3" User-Agent: snom190/3.60x Accept: application/sdp Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer Supported: timer, 100rel, replaces Session-Expires: 3600 Authorization: Digest username="",realm="voip01.r-com.com.au",nonce="4fc82296",uri="sip:@;user=phone",response="c3195cc2866e5d548e55273eff8a67a6",algorithm=md5 Content-Type: application/sdp Content-Length: 370 <-------------> [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 0 [ 50]: INVITE sip:@;user=phone SIP/2.0 [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 1 [ 69]: Via: SIP/2.0/UDP :1026;branch=z9hG4bK-6s3di0ghzfsq;rport [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 2 [ 65]: From: "041 V2" <@>;tag=7z278leqz4 [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 3 [ 41]: To: @;user=phone> [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 4 [ 42]: Call-ID: 3c2675ef6b6c-3y1w8ym6c3ez@snom190 [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 5 [ 14]: CSeq: 2 INVITE [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 7 [ 63]: Contact: <@:1026;line=yqw97773> [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 8 [ 21]: P-Key-Flags: keys="3" [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 9 [ 25]: User-Agent: snom190/3.60x [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 10 [ 23]: Accept: application/sdp [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 11 [ 88]: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 12 [ 31]: Allow-Events: talk, hold, refer [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 13 [ 34]: Supported: timer, 100rel, replaces [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 14 [ 21]: Session-Expires: 3600 [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 15 [193]: Authorization: Digest username="DRA-997896-0041",realm="voip01.r-com.com.au",nonce="4fc82296",uri="sip:@;user=phone",response="c3195cc2866e5d548e55273eff8a67a6",algorithm=md5 [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 16 [ 29]: Content-Type: application/sdp [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 17 [ 19]: Content-Length: 370 [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 18 [ 0]: --- (18 headers 0 lines) --- [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:17896 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE Sending to : 1025 (NAT) [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:16314 handle_request_invite: Initializing initreq for method INVITE - callid 3c2675ef6b6c-3y1w8ym6c3ez@snom190 Using INVITE request as basis request - 3c2675ef6b6c-3y1w8ym6c3ez@snom190 Found user '' for '' [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:3838 do_setnat: Setting NAT on RTP to On [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:3846 do_setnat: Setting NAT on UDPTL to On [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:3763 sip_destroy_user: Destroying user object from memory: [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:16376 handle_request_invite: No SDP in Invite, third party call control [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:16391 handle_request_invite: Checking SIP call limits for device [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:4389 update_call_counter: Updating call counter for incoming call [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:4461 update_call_counter: Call from user '' is 1 out of 1 [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:3763 sip_destroy_user: Destroying user object from memory: Looking for in from-sip4 (domain ) [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:5256 sip_new: *** Our native formats are 0x4 (ulaw) [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:5257 sip_new: *** Joint capabilities are 0x40e (gsm|ulaw|alaw|ilbc) [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:5258 sip_new: *** Our capabilities are 0x40e (gsm|ulaw|alaw|ilbc) [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:5259 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:5287 sip_new: This channel will not be able to handle video. [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:9958 build_route: build_route: Contact hop: <@:1026;line=yqw97773> list_route: hop: @:1026;line=yqw97773> [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:16601 handle_request_invite: SIP/-087f3000: New call is still down.... Trying... <--- Transmitting (NAT) to :1025 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP :1026;branch=z9hG4bK-6s3di0ghzfsq;received=;rport=1025 From: "041 V2" @>;tag=7z278leqz4 To: @;user=phone> Call-ID: 3c2675ef6b6c-3y1w8ym6c3ez@snom190 CSeq: 2 INVITE User-Agent: Asterisk PBX 1.6.0-beta9 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Contact: @> Content-Length: 0 <------------> [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:2521 __sip_xmit: Trying to put 'SIP/2.0 10' onto UDP socket... [Jun 25 14:16:30] DEBUG[76060]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/-087f3000 [Jun 25 14:16:30] DEBUG[76060]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/ [Jun 25 14:16:30] DEBUG[76060]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for SIP - DRA-997896-0041-087f3000 [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:18961 sip_devicestate: Checking device state for peer -087f3000 [Jun 25 14:16:30] DEBUG[76060]: devicestate.c:430 do_state_change: Changing state for SIP/-087f3000 - state 1 (Not in use) [Jun 25 14:16:30] DEBUG[76060]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for SIP - [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:18961 sip_devicestate: Checking device state for peer [Jun 25 14:16:30] DEBUG[76060]: app_queue.c:761 handle_statechange: Device 'SIP/-087f3000' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:19750 build_peer: -REALTIME- peer built. Name: . Peer objects: 2 [Jun 25 14:16:30] DEBUG[76060]: db.c:229 ast_db_del: Unable to find key '' in family 'SIP/Registry' [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:20041 build_peer: Bah, we're expired (16479/1214358111/1214374590)! [Jun 25 14:16:30] DEBUG[76060]: db.c:190 ast_db_get: Unable to find key '' in family 'SIP/Registry' [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:3707 realtime_peer: -REALTIME- loading peer from database to memory. Name: . Peer objects: 2 [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:3465 sip_destroy_peer: Destroying SIP peer [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:3498 sip_destroy_peer: -REALTIME- peer Destroyed. Name: . Realtime Peer objects: 1 [Jun 25 14:16:30] DEBUG[76060]: devicestate.c:430 do_state_change: Changing state for SIP/ - state 5 (Unavailable) [Jun 25 14:16:30] DEBUG[76060]: app_queue.c:761 handle_statechange: Device 'SIP/' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue. -- Executing Set("SIP/-087f3000", "CALLERID(all)") -- Executing Ringing("SIP/-087f3000", "") <--- Transmitting (NAT) to :1025 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP :1026;branch=z9hG4bK-6s3di0ghzfsq;received=;rport=1025 From: "041 V2" @>;tag=7z278leqz4 To: @;user=phone>;tag=as5cbd5e74 Call-ID: 3c2675ef6b6c-3y1w8ym6c3ez@snom190 CSeq: 2 INVITE User-Agent: Asterisk PBX 1.6.0-beta9 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Contact: @> Content-Length: 0 <------------> [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:2521 __sip_xmit: Trying to put 'SIP/2.0 18' onto UDP socket... [Jun 25 14:16:30] DEBUG[76060]: pbx.c:2719 pbx_substitute_variables_helper_full: Function result is '997896' -- Executing NoOp("SIP/-087f3000", "congestion goes here ^ 997896 ^ SIP/-087f3000 ^ 3") [Jun 25 14:16:30] DEBUG[76060]: pbx.c:2719 pbx_substitute_variables_helper_full: Function result is '997896' [Jun 25 14:16:30] DEBUG[76060]: pbx.c:2719 pbx_substitute_variables_helper_full: Function result is 'SIP/CiscoAccount-ISDN2/8' -- Executing Dial("SIP/-087f3000", "SIP/CiscoAccount/8") [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:19046 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:5831 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Jun 25 14:16:30] DEBUG[76060]: chan_sip.c:19750 build_peer: -REALTIME- peer built. Name: CiscoAccount. Peer objects: 2 [Jun 25 14:16:31] DEBUG[76060]: chan_sip.c:3707 realtime_peer: -REALTIME- loading peer from database to memory. Name: CiscoAccount. Peer objects: 2 [Jun 25 14:16:31] DEBUG[76060]: chan_sip.c:3838 do_setnat: Setting NAT on RTP to Off [Jun 25 14:16:31] DEBUG[76060]: chan_sip.c:3846 do_setnat: Setting NAT on UDPTL to Off [Jun 25 14:16:31] DEBUG[76060]: chan_sip.c:2375 obproxy_get: OBPROXY: Not applying OBproxy to this call [Jun 25 14:16:31] DEBUG[76060]: chan_sip.c:3465 sip_destroy_peer: Destroying SIP peer CiscoAccount [Jun 25 14:16:31] DEBUG[76060]: chan_sip.c:3498 sip_destroy_peer: -REALTIME- peer Destroyed. Name: CiscoAccount. Realtime Peer objects: 1 [Jun 25 14:16:31] DEBUG[76060]: acl.c:490 ast_ouraddrfor: Found IP address for this socket [Jun 25 14:16:31] DEBUG[76060]: chan_sip.c:5256 sip_new: *** Our native formats are 0x4 (ulaw) [Jun 25 14:16:31] DEBUG[76060]: chan_sip.c:5257 sip_new: *** Joint capabilities are 0x4 (ulaw) [Jun 25 14:16:31] DEBUG[76060]: chan_sip.c:5258 sip_new: *** Our capabilities are 0x4 (ulaw) [Jun 25 14:16:31] DEBUG[76060]: chan_sip.c:5259 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jun 25 14:16:31] DEBUG[76060]: chan_sip.c:5261 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Jun 25 14:16:31] DEBUG[76060]: chan_sip.c:5287 sip_new: This channel will not be able to handle video. [Jun 25 14:16:31] DEBUG[76060]: channel.c:3705 ast_channel_inherit_variables: Not copying variable ~ODBCFIELDS~. [Jun 25 14:16:31] DEBUG[76060]: channel.c:3705 ast_channel_inherit_variables: Not copying variable ODBCROWS. [Jun 25 14:16:31] DEBUG[76060]: channel.c:3705 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Jun 25 14:16:31] DEBUG[76060]: channel.c:3705 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Jun 25 14:16:31] DEBUG[76060]: channel.c:3705 ast_channel_inherit_variables: Not copying variable SIPURI. [Jun 25 14:16:31] DEBUG[76060]: chan_sip.c:4178 sip_call: Outgoing Call for 8 [Jun 25 14:16:31] DEBUG[76060]: chan_sip.c:4389 update_call_counter: Updating call counter for outgoing call [Jun 25 14:16:31] DEBUG[76060]: chan_sip.c:19750 build_peer: -REALTIME- peer built. Name: CiscoAccount. Peer objects: 2 [Jun 25 14:16:31] DEBUG[76060]: chan_sip.c:3707 realtime_peer: -REALTIME- loading peer from database to memory. Name: CiscoAccount. Peer objects: 2 [Jun 25 14:16:31] DEBUG[76060]: chan_sip.c:4461 update_call_counter: Call to peer 'CiscoAccount' is 1 out of 50 [Jun 25 14:16:31] DEBUG[76060]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/CiscoAccount [Jun 25 14:16:31] DEBUG[76060]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/CiscoAccount [Jun 25 14:16:31] DEBUG[76060]: chan_sip.c:3465 sip_destroy_peer: Destroying SIP peer CiscoAccount [Jun 25 14:16:31] DEBUG[76060]: chan_sip.c:3498 sip_destroy_peer: -REALTIME- peer Destroyed. Name: CiscoAccount. Realtime Peer objects: 1 [Jun 25 14:16:31] DEBUG[76060]: chan_sip.c:4197 sip_call: Our T38 capability (3856), joint T38 capability (3856) [Jun 25 14:16:31] DEBUG[76060]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for CiscoAccount [Jun 25 14:16:31] DEBUG[76060]: chan_sip.c:18961 sip_devicestate: Checking device state for peer CiscoAccount [Jun 25 14:16:31] DEBUG[76060]: chan_sip.c:19750 build_peer: -REALTIME- peer built. Name: CiscoAccount. Peer objects: 2 [Jun 25 14:16:31] DEBUG[76060]: chan_sip.c:19750 build_peer: -REALTIME- peer built. Name: CiscoAccount. Peer objects: 3 [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:3707 realtime_peer: -REALTIME- loading peer from database to memory. Name: CiscoAccount. Peer objects: 3 [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:3465 sip_destroy_peer: Destroying SIP peer CiscoAccount [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:3498 sip_destroy_peer: -REALTIME- peer Destroyed. Name: CiscoAccount. Realtime Peer objects: 2 [Jun 25 14:16:32] DEBUG[76060]: devicestate.c:430 do_state_change: Changing state for SIP/CiscoAccount - state 1 (Not in use) [Jun 25 14:16:32] DEBUG[76060]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for SIP - CiscoAccount [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:18961 sip_devicestate: Checking device state for peer CiscoAccount [Jun 25 14:16:32] DEBUG[76060]: app_queue.c:761 handle_statechange: Device 'SIP/CiscoAccount' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:3707 realtime_peer: -REALTIME- loading peer from database to memory. Name: CiscoAccount. Peer objects: 2 [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:8039 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: False Text flag: False [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:8040 add_sdp: ** Our prefcodec: 0x4 (ulaw) Audio is at port 14294 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:8193 add_sdp: -- Done with adding codecs to SDP [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:8258 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:2313 initialize_initreq: Initializing initreq for method INVITE - callid 3a2fed366bfe72d57724370e4a27b524@ [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 0 [ 41]: INVITE sip:8@CiscoIP SIP/2.0 [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 1 [ 64]: Via: SIP/2.0/UDP :5060;branch=z9hG4bK57f40c9f;rport [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 3 [ 60]: From: "MyCallerID" >;tag=as1f647b87 [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 4 [ 32]: To: @CiscoIP> [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 5 [ 37]: Contact: > [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 6 [ 55]: Call-ID: 3a2fed366bfe72d57724370e4a27b524@ [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 7 [ 16]: CSeq: 102 INVITE [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 8 [ 36]: User-Agent: Asterisk PBX 1.6.0-beta9 [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 9 [ 35]: Date: Wed, 25 Jun 2008 06:16:31 GMT [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 10 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 11 [ 26]: Supported: replaces, timer [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 12 [ 29]: Content-Type: application/sdp [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 13 [ 19]: Content-Length: 269 [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 14 [ 0]: [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:6142 parse_request: Body 0 [ 3]: v=0 [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:6142 parse_request: Body 1 [ 49]: o=root 1778378404 1778378404 IN IP4 [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:6142 parse_request: Body 2 [ 26]: s=Asterisk PBX 1.6.0-beta9 [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:6142 parse_request: Body 3 [ 22]: c=IN IP4 [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:6142 parse_request: Body 4 [ 5]: t=0 0 [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:6142 parse_request: Body 5 [ 27]: m=audio 14294 RTP/AVP 0 101 [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:6142 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:6142 parse_request: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:6142 parse_request: Body 8 [ 15]: a=fmtp:101 0-16 [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:6142 parse_request: Body 9 [ 25]: a=silenceSupp:off - - - - [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:6142 parse_request: Body 10 [ 10]: a=ptime:20 [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:6142 parse_request: Body 11 [ 10]: a=sendrecv Reliably Transmitting (no NAT) to CiscoIP:5060: INVITE sip:8@CiscoIP SIP/2.0 Via: SIP/2.0/UDP :5060;branch=z9hG4bK57f40c9f;rport Max-Forwards: 70 From: "MyCallerID" >;tag=as1f647b87 To: @CiscoIP> Contact: > Call-ID: 3a2fed366bfe72d57724370e4a27b524@ CSeq: 102 INVITE User-Agent: Asterisk PBX 1.6.0-beta9 Date: Wed, 25 Jun 2008 06:16:31 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Content-Type: application/sdp Content-Length: 269 v=0 o=root 1778378404 1778378404 IN IP4 s=Asterisk PBX 1.6.0-beta9 c=IN IP4 t=0 0 m=audio 14294 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:2838 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #11 [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:2521 __sip_xmit: Trying to put 'INVITE sip' onto UDP socket... -- Called CiscoAccount/8 [Jun 25 14:16:32] DEBUG[76060]: devicestate.c:430 do_state_change: Changing state for SIP/CiscoAccount - state 2 (In use) [Jun 25 14:16:32] DEBUG[76060]: app_queue.c:761 handle_statechange: Device 'SIP/CiscoAccount' changed to state '2' (In use) but we don't care because they're not a member of any queue. oip01*CLI> <--- SIP read from UDP://CiscoIP:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP :5060;branch=z9hG4bK57f40c9f;rport From: "MyCallerID" >;tag=as1f647b87 To: @CiscoIP>;tag=9E37C020-15C2 Date: Wed, 25 Jun 2008 06:25:37 GMT Call-ID: 3a2fed366bfe72d57724370e4a27b524@ Server: Cisco-SIPGateway/IOS-12.x CSeq: 102 INVITE Allow-Events: telephone-event Content-Length: 0 <-------------> [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 0 [ 18]: SIP/2.0 100 Trying [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 1 [ 64]: Via: SIP/2.0/UDP :5060;branch=z9hG4bK57f40c9f;rport [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 2 [ 60]: From: "MyCallerID" >;tag=as1f647b87 [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 3 [ 50]: To: @CiscoIP>;tag=9E37C020-15C2 [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 4 [ 35]: Date: Wed, 25 Jun 2008 06:25:37 GMT [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 5 [ 55]: Call-ID: 3a2fed366bfe72d57724370e4a27b524@ [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 6 [ 33]: Server: Cisco-SIPGateway/IOS-12.x [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 7 [ 16]: CSeq: 102 INVITE [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 8 [ 29]: Allow-Events: telephone-event [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 9 [ 17]: Content-Length: 0 [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 10 [ 0]: --- (10 headers 0 lines) --- [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:3030 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #11 - INVITE (got response) [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:3037 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '3a2fed366bfe72d57724370e4a27b524@' Request 102: Found [Jun 25 14:16:32] DEBUG[76060]: chan_sip.c:14515 handle_response_invite: SIP response 100 to standard invite oip01*CLI> <--- SIP read from UDP://CiscoIP:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP :5060;branch=z9hG4bK57f40c9f;rport From: "MyCallerID" >;tag=as1f647b87 To: @CiscoIP>;tag=9E37C020-15C2 Date: Wed, 25 Jun 2008 06:25:37 GMT Call-ID: 3a2fed366bfe72d57724370e4a27b524@ Server: Cisco-SIPGateway/IOS-12.x CSeq: 102 INVITE Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER Allow-Events: telephone-event Contact: @CiscoIP:5060> Content-Length: 0 <-------------> [Jun 25 14:16:35] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 0 [ 19]: SIP/2.0 180 Ringing [Jun 25 14:16:35] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 1 [ 64]: Via: SIP/2.0/UDP :5060;branch=z9hG4bK57f40c9f;rport [Jun 25 14:16:35] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 2 [ 60]: From: "MyCallerID" >;tag=as1f647b87 [Jun 25 14:16:35] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 3 [ 50]: To: @CiscoIP>;tag=9E37C020-15C2 [Jun 25 14:16:35] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 4 [ 35]: Date: Wed, 25 Jun 2008 06:25:37 GMT [Jun 25 14:16:35] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 5 [ 55]: Call-ID: 3a2fed366bfe72d57724370e4a27b524@ [Jun 25 14:16:35] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 6 [ 33]: Server: Cisco-SIPGateway/IOS-12.x [Jun 25 14:16:35] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 7 [ 16]: CSeq: 102 INVITE [Jun 25 14:16:35] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 8 [104]: Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER [Jun 25 14:16:35] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 9 [ 29]: Allow-Events: telephone-event [Jun 25 14:16:35] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 10 [ 42]: Contact: @CiscoIP:5060> [Jun 25 14:16:35] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 11 [ 17]: Content-Length: 0 [Jun 25 14:16:35] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 12 [ 0]: --- (12 headers 0 lines) --- [Jun 25 14:16:35] DEBUG[76060]: chan_sip.c:3037 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '3a2fed366bfe72d57724370e4a27b524@' Request 102: Found [Jun 25 14:16:35] DEBUG[76060]: chan_sip.c:14515 handle_response_invite: SIP response 180 to standard invite [Jun 25 14:16:35] DEBUG[76060]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/CiscoAccount-087fe000 [Jun 25 14:16:35] DEBUG[76060]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/CiscoAccount [Jun 25 14:16:35] DEBUG[76060]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for SIP - CiscoAccount-087fe000 [Jun 25 14:16:35] DEBUG[76060]: chan_sip.c:18961 sip_devicestate: Checking device state for peer CiscoAccount-087fe000 -- SIP/CiscoAccount-087fe000 is ringing <--- Transmitting (NAT) to :1025 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP :1026;branch=z9hG4bK-6s3di0ghzfsq;received=;rport=1025 From: "041 V2" @>;tag=7z278leqz4 To: @;user=phone>;tag=as5cbd5e74 Call-ID: 3c2675ef6b6c-3y1w8ym6c3ez@snom190 CSeq: 2 INVITE User-Agent: Asterisk PBX 1.6.0-beta9 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Contact: @> Content-Length: 0 <------------> [Jun 25 14:16:35] DEBUG[76060]: chan_sip.c:2521 __sip_xmit: Trying to put 'SIP/2.0 18' onto UDP socket... [Jun 25 14:16:35] DEBUG[76060]: devicestate.c:430 do_state_change: Changing state for SIP/CiscoAccount-087fe000 - state 1 (Not in use) [Jun 25 14:16:35] DEBUG[76060]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for SIP - CiscoAccount [Jun 25 14:16:35] DEBUG[76060]: chan_sip.c:18961 sip_devicestate: Checking device state for peer CiscoAccount [Jun 25 14:16:35] DEBUG[76060]: app_queue.c:761 handle_statechange: Device 'SIP/CiscoAccount-087fe000' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 25 14:16:35] DEBUG[76060]: chan_sip.c:19750 build_peer: -REALTIME- peer built. Name: CiscoAccount. Peer objects: 3 [Jun 25 14:16:36] DEBUG[76060]: chan_sip.c:3707 realtime_peer: -REALTIME- loading peer from database to memory. Name: CiscoAccount. Peer objects: 3 [Jun 25 14:16:36] DEBUG[76060]: chan_sip.c:3465 sip_destroy_peer: Destroying SIP peer CiscoAccount [Jun 25 14:16:36] DEBUG[76060]: chan_sip.c:3498 sip_destroy_peer: -REALTIME- peer Destroyed. Name: CiscoAccount. Realtime Peer objects: 2 [Jun 25 14:16:36] DEBUG[76060]: devicestate.c:430 do_state_change: Changing state for SIP/CiscoAccount - state 1 (Not in use) [Jun 25 14:16:36] DEBUG[76060]: app_queue.c:761 handle_statechange: Device 'SIP/CiscoAccount' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. oip01*CLI> <--- SIP read from UDP://CiscoIP:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP :5060;branch=z9hG4bK57f40c9f;rport From: "MyCallerID" >;tag=as1f647b87 To: @CiscoIP>;tag=9E37C020-15C2 Date: Wed, 25 Jun 2008 06:25:37 GMT Call-ID: 3a2fed366bfe72d57724370e4a27b524@ Server: Cisco-SIPGateway/IOS-12.x CSeq: 102 INVITE Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER Allow-Events: telephone-event Contact: @CiscoIP:5060> Content-Type: application/sdp Content-Length: 251 v=0 o=CiscoSystemsSIP-GW-UserAgent 9153 48 IN IP4 CiscoIP s=SIP Call c=IN IP4 CiscoIP t=0 0 m=audio 18076 RTP/AVP 0 101 c=IN IP4 CiscoIP a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 <-------------> [Jun 25 14:16:38] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Jun 25 14:16:38] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 1 [ 64]: Via: SIP/2.0/UDP :5060;branch=z9hG4bK57f40c9f;rport [Jun 25 14:16:38] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 2 [ 60]: From: "MyCallerID" >;tag=as1f647b87 [Jun 25 14:16:38] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 3 [ 50]: To: @CiscoIP>;tag=9E37C020-15C2 [Jun 25 14:16:38] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 4 [ 35]: Date: Wed, 25 Jun 2008 06:25:37 GMT [Jun 25 14:16:38] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 5 [ 55]: Call-ID: 3a2fed366bfe72d57724370e4a27b524@ [Jun 25 14:16:38] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 6 [ 33]: Server: Cisco-SIPGateway/IOS-12.x [Jun 25 14:16:38] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 7 [ 16]: CSeq: 102 INVITE [Jun 25 14:16:38] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 8 [104]: Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER [Jun 25 14:16:38] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 9 [ 29]: Allow-Events: telephone-event [Jun 25 14:16:38] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 10 [ 42]: Contact: @CiscoIP:5060> [Jun 25 14:16:38] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 11 [ 29]: Content-Type: application/sdp [Jun 25 14:16:38] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 12 [ 19]: Content-Length: 251 [Jun 25 14:16:38] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 13 [ 0]: [Jun 25 14:16:38] DEBUG[76060]: chan_sip.c:6142 parse_request: Body 0 [ 3]: v=0 [Jun 25 14:16:38] DEBUG[76060]: chan_sip.c:6142 parse_request: Body 1 [ 60]: o=CiscoSystemsSIP-GW-UserAgent 9153 48 IN IP4 CiscoIP [Jun 25 14:16:38] DEBUG[76060]: chan_sip.c:6142 parse_request: Body 2 [ 10]: s=SIP Call [Jun 25 14:16:38] DEBUG[76060]: chan_sip.c:6142 parse_request: Body 3 [ 23]: c=IN IP4 CiscoIP [Jun 25 14:16:38] DEBUG[76060]: chan_sip.c:6142 parse_request: Body 4 [ 5]: t=0 0 [Jun 25 14:16:38] DEBUG[76060]: chan_sip.c:6142 parse_request: Body 5 [ 27]: m=audio 18076 RTP/AVP 0 101 [Jun 25 14:16:38] DEBUG[76060]: chan_sip.c:6142 parse_request: Body 6 [ 23]: c=IN IP4 CiscoIP [Jun 25 14:16:38] DEBUG[76060]: chan_sip.c:6142 parse_request: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Jun 25 14:16:38] DEBUG[76060]: chan_sip.c:6142 parse_request: Body 8 [ 33]: a=rtpmap:101 telephone-event/8000 [Jun 25 14:16:38] DEBUG[76060]: chan_sip.c:6142 parse_request: Body 9 [ 15]: a=fmtp:101 0-16 [Jun 25 14:16:38] DEBUG[76060]: chan_sip.c:6142 parse_request: Body 10 [ 10]: a=ptime:20 --- (13 headers 11 lines) --- [Jun 25 14:16:38] DEBUG[76060]: chan_sip.c:2962 __sip_ack: Acked pending invite 102 [Jun 25 14:16:38] DEBUG[76060]: chan_sip.c:2997 __sip_ack: Stopping retransmission on '3a2fed366bfe72d57724370e4a27b524@' of Request 102: Match Found [Jun 25 14:16:38] DEBUG[76060]: chan_sip.c:14515 handle_response_invite: SIP response 200 to standard invite Found RTP audio format 0 Found RTP audio format 101 [Jun 25 14:16:38] DEBUG[76060]: chan_sip.c:6563 process_sdp: Peer doesn't provide T.38 UDPTL Peer audio RTP is at port CiscoIP:18076 Found audio description format PCMU for ID 0 Found audio description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x4 (ulaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port CiscoIP:18076 [Jun 25 14:16:38] DEBUG[76060]: chan_sip.c:6915 process_sdp: We're settling with these formats: 0x4 (ulaw) [Jun 25 14:16:38] DEBUG[76060]: chan_sip.c:6920 process_sdp: We have an owner, now see if we need to change this call [Jun 25 14:16:38] DEBUG[76060]: chan_sip.c:4389 update_call_counter: Updating call counter for outgoing call [Jun 25 14:16:38] DEBUG[76060]: chan_sip.c:19750 build_peer: -REALTIME- peer built. Name: CiscoAccount. Peer objects: 3 [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:3707 realtime_peer: -REALTIME- loading peer from database to memory. Name: CiscoAccount. Peer objects: 3 [Jun 25 14:16:39] DEBUG[76060]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/CiscoAccount [Jun 25 14:16:39] DEBUG[76060]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/CiscoAccount [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:3465 sip_destroy_peer: Destroying SIP peer CiscoAccount [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:3498 sip_destroy_peer: -REALTIME- peer Destroyed. Name: CiscoAccount. Realtime Peer objects: 2 --- set_address_from_contact host 'CiscoIP' [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:9958 build_route: build_route: Contact hop: @CiscoIP:5060> list_route: hop: @CiscoIP:5060> [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:7361 reqprep: Strict routing enforced for session 3a2fed366bfe72d57724370e4a27b524@ set_destination: Parsing @CiscoIP:5060> for address/port to send to set_destination: set destination to CiscoIP, port 5060 Transmitting (no NAT) to CiscoIP:5060: ACK sip:8@CiscoIP:5060 SIP/2.0 Via: SIP/2.0/UDP :5060;branch=z9hG4bK4b9063b1;rport Max-Forwards: 70 From: "MyCallerID" >;tag=as1f647b87 To: @CiscoIP>;tag=9E37C020-15C2 Contact: > Call-ID: 3a2fed366bfe72d57724370e4a27b524@ CSeq: 102 ACK User-Agent: Asterisk PBX 1.6.0-beta9 Content-Length: 0 --- [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:2521 __sip_xmit: Trying to put 'ACK sip:81' onto UDP socket... <--- SIP read from UDP://CiscoIP:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP :5060;branch=z9hG4bK57f40c9f;rport From: "MyCallerID" >;tag=as1f647b87 To: @CiscoIP>;tag=9E37C020-15C2 Date: Wed, 25 Jun 2008 06:25:37 GMT Call-ID: 3a2fed366bfe72d57724370e4a27b524@ Server: Cisco-SIPGateway/IOS-12.x CSeq: 102 INVITE Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER Allow-Events: telephone-event Contact: @CiscoIP:5060> Content-Type: application/sdp Content-Length: 251 v=0 o=CiscoSystemsSIP-GW-UserAgent 9153 48 IN IP4 CiscoIP s=SIP Call c=IN IP4 CiscoIP t=0 0 m=audio 18076 RTP/AVP 0 101 c=IN IP4 CiscoIP a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 <-------------> [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 1 [ 64]: Via: SIP/2.0/UDP :5060;branch=z9hG4bK57f40c9f;rport [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 2 [ 60]: From: "MyCallerID" >;tag=as1f647b87 [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 3 [ 50]: To: @CiscoIP>;tag=9E37C020-15C2 [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 4 [ 35]: Date: Wed, 25 Jun 2008 06:25:37 GMT [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 5 [ 55]: Call-ID: 3a2fed366bfe72d57724370e4a27b524@ [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 6 [ 33]: Server: Cisco-SIPGateway/IOS-12.x [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 7 [ 16]: CSeq: 102 INVITE [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 8 [104]: Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO, UPDATE, REGISTER [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 9 [ 29]: Allow-Events: telephone-event [Jun 25 14:16:39] DEBUG[76060]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for SIP - CiscoAccount [Jun 25 14:16:39] DEBUG[76060]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/CiscoAccount-087fe000 [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 10 [ 42]: Contact: @CiscoIP:5060> [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:18961 sip_devicestate: Checking device state for peer CiscoAccount [Jun 25 14:16:39] DEBUG[76060]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/CiscoAccount [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 11 [ 29]: Content-Type: application/sdp -- SIP/CiscoAccount-087fe000 answered SIP/-087f3000 [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 12 [ 19]: Content-Length: 251 [Jun 25 14:16:39] DEBUG[76060]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/-087f3000 [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 13 [ 0]: [Jun 25 14:16:39] DEBUG[76060]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/ [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:6142 parse_request: Body 0 [ 3]: v=0 [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:4859 sip_answer: SIP answering channel: SIP/-087f3000 [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:8315 transmit_response_with_sdp: Setting framing from config on incoming call [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:8039 add_sdp: ** Our capability: 0x40e (gsm|ulaw|alaw|ilbc) Video flag: False Text flag: False [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:6142 parse_request: Body 1 [ 60]: o=CiscoSystemsSIP-GW-UserAgent 9153 48 IN IP4 CiscoIP [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:8040 add_sdp: ** Our prefcodec: 0x0 (nothing) [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:6142 parse_request: Body 2 [ 10]: s=SIP Call Audio is at port 14904 Adding codec 0x4 (ulaw) to SDP [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:6142 parse_request: Body 3 [ 23]: c=IN IP4 CiscoIP Adding codec 0x8 (alaw) to SDP [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:6142 parse_request: Body 4 [ 5]: t=0 0 Adding codec 0x400 (ilbc) to SDP [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:6142 parse_request: Body 5 [ 27]: m=audio 18076 RTP/AVP 0 101 Adding codec 0x2 (gsm) to SDP [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:6142 parse_request: Body 6 [ 23]: c=IN IP4 CiscoIP Adding non-codec 0x1 (telephone-event) to SDP [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:6142 parse_request: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:8193 add_sdp: -- Done with adding codecs to SDP [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:6142 parse_request: Body 8 [ 33]: a=rtpmap:101 telephone-event/8000 [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:8258 add_sdp: Done building SDP. Settling with this capability: 0x40e (gsm|ulaw|alaw|ilbc) [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:6142 parse_request: Body 9 [ 15]: a=fmtp:101 0-16 <--- Reliably Transmitting (NAT) to :1025 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP :1026;branch=z9hG4bK-6s3di0ghzfsq;received=;rport=1025 From: "041 V2" @>;tag=7z278leqz4 To: @;user=phone>;tag=as5cbd5e74 Call-ID: 3c2675ef6b6c-3y1w8ym6c3ez@snom190 CSeq: 2 INVITE User-Agent: Asterisk PBX 1.6.0-beta9 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Contact: @> Content-Type: application/sdp Content-Length: 361 v=0 o=root 1889796833 1889796833 IN IP4 s=Asterisk PBX 1.6.0-beta9 c=IN IP4 t=0 0 m=audio 14904 RTP/AVP 0 8 97 3 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:97 iLBC/8000 a=fmtp:97 mode=30 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:6142 parse_request: Body 10 [ 10]: a=ptime:20 [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:2838 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #13 --- (13 headers 11 lines) --- [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:2521 __sip_xmit: Trying to put 'SIP/2.0 20' onto UDP socket... [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:2997 __sip_ack: Stopping retransmission on '3a2fed366bfe72d57724370e4a27b524@' of Request 102: Match Not Found [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:14513 handle_response_invite: SIP response 200 to RE-invite on outgoing call 3a2fed366bfe72d57724370e4a27b524@ [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:6400 process_sdp: SDP version number same as previous SDP [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:4389 update_call_counter: Updating call counter for outgoing call [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:19750 build_peer: -REALTIME- peer built. Name: CiscoAccount. Peer objects: 3 [Jun 25 14:16:39] DEBUG[76060]: chan_sip.c:19750 build_peer: -REALTIME- peer built. Name: CiscoAccount. Peer objects: 4 [Jun 25 14:16:40] DEBUG[76060]: chan_sip.c:3707 realtime_peer: -REALTIME- loading peer from database to memory. Name: CiscoAccount. Peer objects: 4 [Jun 25 14:16:40] DEBUG[76060]: chan_sip.c:3465 sip_destroy_peer: Destroying SIP peer CiscoAccount [Jun 25 14:16:40] DEBUG[76060]: chan_sip.c:3498 sip_destroy_peer: -REALTIME- peer Destroyed. Name: CiscoAccount. Realtime Peer objects: 3 [Jun 25 14:16:40] DEBUG[76060]: devicestate.c:430 do_state_change: Changing state for SIP/CiscoAccount - state 1 (Not in use) [Jun 25 14:16:40] DEBUG[76060]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for SIP - CiscoAccount [Jun 25 14:16:40] DEBUG[76060]: chan_sip.c:18961 sip_devicestate: Checking device state for peer CiscoAccount [Jun 25 14:16:40] DEBUG[76060]: app_queue.c:761 handle_statechange: Device 'SIP/CiscoAccount' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1134 channel_find_locked: Failure, could not lock '0x8800000' after 199 retries! [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1134 channel_find_locked: Failure, could not lock '0x8800000' after 199 retries! [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1134 channel_find_locked: Failure, could not lock '0x8800000' after 199 retries! [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' [Jun 25 14:16:40] DEBUG[76060]: channel.c:1129 channel_find_locked: Avoiding initial deadlock for channel '0x8800000' --- set_address_from_contact host 'CiscoIP' --- (9 headers 0 lines) --- [Jun 25 14:16:40] DEBUG[76060]: chan_sip.c:3707 realtime_peer: -REALTIME- loading peer from database to memory. Name: CiscoAccount. Peer objects: 3 [Jun 25 14:16:40] DEBUG[76060]: chan_sip.c:3465 sip_destroy_peer: Destroying SIP peer CiscoAccount [Jun 25 14:16:40] DEBUG[76060]: chan_sip.c:3498 sip_destroy_peer: -REALTIME- peer Destroyed. Name: CiscoAccount. Realtime Peer objects: 2 [Jun 25 14:16:40] DEBUG[76060]: devicestate.c:430 do_state_change: Changing state for SIP/CiscoAccount - state 1 (Not in use) [Jun 25 14:16:40] DEBUG[76060]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for SIP - [Jun 25 14:16:40] DEBUG[76060]: chan_sip.c:18961 sip_devicestate: Checking device state for peer -087f3000 [Jun 25 14:16:40] DEBUG[76060]: app_queue.c:761 handle_statechange: Device 'SIP/CiscoAccount' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 25 14:16:41] DEBUG[76060]: devicestate.c:430 do_state_change: Changing state for SIP/-087f3000 - state 1 (Not in use) [Jun 25 14:16:41] DEBUG[76060]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for SIP - [Jun 25 14:16:41] DEBUG[76060]: chan_sip.c:18961 sip_devicestate: Checking device state for peer [Jun 25 14:16:41] DEBUG[76060]: app_queue.c:761 handle_statechange: Device 'SIP/-087f3000' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 25 14:16:41] DEBUG[76060]: chan_sip.c:19750 build_peer: -REALTIME- peer built. Name: . Peer objects: 3 [Jun 25 14:16:41] DEBUG[76060]: db.c:229 ast_db_del: Unable to find key '' in family 'SIP/Registry' [Jun 25 14:16:41] DEBUG[76060]: chan_sip.c:20041 build_peer: Bah, we're expired (16490/1214358111/1214374601)! [Jun 25 14:16:41] DEBUG[76060]: db.c:190 ast_db_get: Unable to find key '' in family 'SIP/Registry' [Jun 25 14:16:41] DEBUG[76060]: chan_sip.c:3707 realtime_peer: -REALTIME- loading peer from database to memory. Name: . Peer objects: 3 [Jun 25 14:16:41] DEBUG[76060]: chan_sip.c:3465 sip_destroy_peer: Destroying SIP peer [Jun 25 14:16:41] DEBUG[76060]: chan_sip.c:3498 sip_destroy_peer: -REALTIME- peer Destroyed. Name: . Realtime Peer objects: 2 [Jun 25 14:16:41] DEBUG[76060]: devicestate.c:430 do_state_change: Changing state for SIP/ - state 5 (Unavailable) [Jun 25 14:16:41] DEBUG[76060]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for SIP - CiscoAccount [Jun 25 14:16:41] DEBUG[76060]: chan_sip.c:18961 sip_devicestate: Checking device state for peer CiscoAccount [Jun 25 14:16:41] DEBUG[76060]: app_queue.c:761 handle_statechange: Device 'SIP/' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue. [Jun 25 14:16:41] DEBUG[76060]: chan_sip.c:19750 build_peer: -REALTIME- peer built. Name: CiscoAccount. Peer objects: 3 [Jun 25 14:16:41] DEBUG[76060]: rtp.c:1101 ast_rtcp_read: Got RTCP report of 136 bytes [Jun 25 14:16:41] DEBUG[76060]: chan_sip.c:3707 realtime_peer: -REALTIME- loading peer from database to memory. Name: CiscoAccount. Peer objects: 3 [Jun 25 14:16:41] DEBUG[76060]: chan_sip.c:3465 sip_destroy_peer: Destroying SIP peer CiscoAccount [Jun 25 14:16:41] DEBUG[76060]: chan_sip.c:3498 sip_destroy_peer: -REALTIME- peer Destroyed. Name: CiscoAccount. Realtime Peer objects: 2 [Jun 25 14:16:41] DEBUG[76060]: devicestate.c:430 do_state_change: Changing state for SIP/CiscoAccount - state 1 (Not in use) [Jun 25 14:16:41] DEBUG[76060]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for SIP - CiscoAccount [Jun 25 14:16:41] DEBUG[76060]: chan_sip.c:18961 sip_devicestate: Checking device state for peer CiscoAccount [Jun 25 14:16:41] DEBUG[76060]: app_queue.c:761 handle_statechange: Device 'SIP/CiscoAccount' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 25 14:16:41] DEBUG[76060]: devicestate.c:430 do_state_change: Changing state for SIP/CiscoAccount - state 2 (In use) [Jun 25 14:16:41] DEBUG[76060]: app_queue.c:761 handle_statechange: Device 'SIP/CiscoAccount' changed to state '2' (In use) but we don't care because they're not a member of any queue. oip01*CLI> <--- SIP read from UDP://:1025 ---> BYE sip:@ SIP/2.0 Via: SIP/2.0/UDP :1026;branch=z9hG4bK-4fnezt5bgidg;rport From: "041 V2" @>;tag=7z278leqz4 To: @;user=phone>;tag=as5cbd5e74 Call-ID: 3c2675ef6b6c-3y1w8ym6c3ez@snom190 CSeq: 3 BYE Max-Forwards: 70 Contact: @:1026;line=yqw97773> User-Agent: snom190/3.60x Content-Length: 0 <-------------> [Jun 25 14:16:43] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 0 [ 36]: BYE sip:@ SIP/2.0 [Jun 25 14:16:43] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 1 [ 69]: Via: SIP/2.0/UDP :1026;branch=z9hG4bK-4fnezt5bgidg;rport [Jun 25 14:16:43] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 2 [ 65]: From: "041 V2" <@>;tag=7z278leqz4 [Jun 25 14:16:43] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 3 [ 56]: To: @;user=phone>;tag=as5cbd5e74 [Jun 25 14:16:43] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 4 [ 42]: Call-ID: 3c2675ef6b6c-3y1w8ym6c3ez@snom190 [Jun 25 14:16:43] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 5 [ 11]: CSeq: 3 BYE [Jun 25 14:16:43] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Jun 25 14:16:43] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 7 [ 63]: Contact: <@:1026;line=yqw97773> [Jun 25 14:16:43] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 8 [ 25]: User-Agent: snom190/3.60x [Jun 25 14:16:43] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 9 [ 17]: Content-Length: 0 [Jun 25 14:16:43] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 10 [ 0]: --- (10 headers 0 lines) --- [Jun 25 14:16:43] DEBUG[76060]: chan_sip.c:17896 handle_incoming: **** Received BYE (8) - Command in SIP BYE [Jun 25 14:16:43] DEBUG[76060]: chan_sip.c:17366 handle_request_bye: Initializing initreq for method BYE - callid 3c2675ef6b6c-3y1w8ym6c3ez@snom190 Sending to : 1025 (NAT) [Jun 25 14:16:43] DEBUG[76060]: chan_sip.c:2324 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 3c2675ef6b6c-3y1w8ym6c3ez@snom190 [Jun 25 14:16:43] DEBUG[76060]: chan_sip.c:17423 handle_request_bye: Received bye, issuing owner hangup <--- Transmitting (NAT) to :1025 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP :1026;branch=z9hG4bK-4fnezt5bgidg;received=;rport=1025 From: "041 V2" @>;tag=7z278leqz4 To: @;user=phone>;tag=as5cbd5e74 Call-ID: 3c2675ef6b6c-3y1w8ym6c3ez@snom190 CSeq: 3 BYE User-Agent: Asterisk PBX 1.6.0-beta9 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Contact: @> Content-Length: 0 <------------> [Jun 25 14:16:43] DEBUG[76060]: chan_sip.c:2521 __sip_xmit: Trying to put 'SIP/2.0 20' onto UDP socket... [Jun 25 14:16:43] DEBUG[76060]: rtp.c:3621 bridge_p2p_loop: p2p-rtp-bridge: Ooh, got a hangup [Jun 25 14:16:43] DEBUG[76060]: channel.c:4475 ast_channel_bridge: Returning from native bridge, channels: SIP/-087f3000, SIP/CiscoAccount-087fe000 [Jun 25 14:16:43] DEBUG[76060]: channel.c:1617 ast_hangup: Hanging up channel 'SIP/CiscoAccount-087fe000' [Jun 25 14:16:43] DEBUG[76060]: chan_sip.c:4697 sip_hangup: Hangup call SIP/CiscoAccount-087fe000, SIP callid 3a2fed366bfe72d57724370e4a27b524@ [Jun 25 14:16:43] DEBUG[76060]: chan_sip.c:4702 sip_hangup: update_call_counter(8) - decrement call limit counter on hangup [Jun 25 14:16:43] DEBUG[76060]: chan_sip.c:4389 update_call_counter: Updating call counter for outgoing call [Jun 25 14:16:43] DEBUG[76060]: chan_sip.c:19750 build_peer: -REALTIME- peer built. Name: CiscoAccount. Peer objects: 3 [Jun 25 14:16:44] DEBUG[76060]: chan_sip.c:3707 realtime_peer: -REALTIME- loading peer from database to memory. Name: CiscoAccount. Peer objects: 3 [Jun 25 14:16:44] DEBUG[76060]: chan_sip.c:4435 update_call_counter: Call to peer 'CiscoAccount' removed from call limit 50 [Jun 25 14:16:44] DEBUG[76060]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/CiscoAccount [Jun 25 14:16:44] DEBUG[76060]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/CiscoAccount [Jun 25 14:16:44] DEBUG[76060]: chan_sip.c:3465 sip_destroy_peer: Destroying SIP peer CiscoAccount [Jun 25 14:16:44] DEBUG[76060]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for SIP - CiscoAccount [Jun 25 14:16:44] DEBUG[76060]: chan_sip.c:3498 sip_destroy_peer: -REALTIME- peer Destroyed. Name: CiscoAccount. Realtime Peer objects: 2 Scheduling destruction of SIP dialog '3a2fed366bfe72d57724370e4a27b524@' in 32000 ms (Method: INVITE) [Jun 25 14:16:44] DEBUG[76060]: chan_sip.c:18961 sip_devicestate: Checking device state for peer CiscoAccount [Jun 25 14:16:44] DEBUG[76060]: chan_sip.c:7361 reqprep: Strict routing enforced for session 3a2fed366bfe72d57724370e4a27b524@ set_destination: Parsing @CiscoIP:5060> for address/port to send to set_destination: set destination to CiscoIP, port 5060 Reliably Transmitting (no NAT) to CiscoIP:5060: BYE sip:8@CiscoIP:5060 SIP/2.0 Via: SIP/2.0/UDP :5060;branch=z9hG4bK5e51b62f;rport Max-Forwards: 70 From: "MyCallerID" >;tag=as1f647b87 To: @CiscoIP>;tag=9E37C020-15C2 Call-ID: 3a2fed366bfe72d57724370e4a27b524@ CSeq: 103 BYE User-Agent: Asterisk PBX 1.6.0-beta9 Content-Length: 0 --- [Jun 25 14:16:44] DEBUG[76060]: chan_sip.c:2838 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #15 [Jun 25 14:16:44] DEBUG[76060]: chan_sip.c:2521 __sip_xmit: Trying to put 'BYE sip:81' onto UDP socket... [Jun 25 14:16:44] DEBUG[76060]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/CiscoAccount-087fe000 [Jun 25 14:16:44] DEBUG[76060]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/CiscoAccount [Jun 25 14:16:44] DEBUG[76060]: rtp.c:1833 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Jun 25 14:16:44] DEBUG[76060]: app_dial.c:1940 dial_exec_full: Exiting with DIALSTATUS=ANSWER. oip01*CLI> <--- SIP read from UDP://CiscoIP:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP :5060;branch=z9hG4bK5e51b62f;rport From: "MyCallerID" >;tag=as1f647b87 To: @CiscoIP>;tag=9E37C020-15C2 Date: Wed, 25 Jun 2008 06:25:48 GMT Call-ID: 3a2fed366bfe72d57724370e4a27b524@ Server: Cisco-SIPGateway/IOS-12.x Content-Length: 0 CSeq: 103 BYE <-------------> [Jun 25 14:16:44] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Jun 25 14:16:44] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 1 [ 64]: Via: SIP/2.0/UDP :5060;branch=z9hG4bK5e51b62f;rport [Jun 25 14:16:44] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 2 [ 60]: From: "MyCallerID" >;tag=as1f647b87 [Jun 25 14:16:44] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 3 [ 50]: To: @CiscoIP>;tag=9E37C020-15C2 [Jun 25 14:16:44] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 4 [ 35]: Date: Wed, 25 Jun 2008 06:25:48 GMT [Jun 25 14:16:44] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 5 [ 55]: Call-ID: 3a2fed366bfe72d57724370e4a27b524@ [Jun 25 14:16:44] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 6 [ 33]: Server: Cisco-SIPGateway/IOS-12.x [Jun 25 14:16:44] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 7 [ 17]: Content-Length: 0 [Jun 25 14:16:44] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 8 [ 13]: CSeq: 103 BYE [Jun 25 14:16:44] DEBUG[76060]: chan_sip.c:6142 parse_request: Header 9 [ 0]: --- (9 headers 0 lines) --- [Jun 25 14:16:44] DEBUG[76060]: chan_sip.c:2967 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #15 [Jun 25 14:16:44] DEBUG[76060]: chan_sip.c:2997 __sip_ack: Stopping retransmission on '3a2fed366bfe72d57724370e4a27b524@' of Request 103: Match Found Really destroying SIP dialog '3a2fed366bfe72d57724370e4a27b524@' Method: INVITE [Jun 25 14:16:44] DEBUG[76060]: chan_sip.c:19750 build_peer: -REALTIME- peer built. Name: CiscoAccount. Peer objects: 3 -- Auto fallthrough, channel 'SIP/-087f3000' status is 'ANSWER' [Jun 25 14:16:44] DEBUG[76060]: channel.c:1518 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/-087f3000' -- Executing Hangup("SIP/-087f3000", "") [Jun 25 14:16:44] DEBUG[76060]: channel.c:1617 ast_hangup: Hanging up channel 'SIP/-087f3000' [Jun 25 14:16:44] DEBUG[76060]: chan_sip.c:4697 sip_hangup: Hangup call SIP/-087f3000, SIP callid 3c2675ef6b6c-3y1w8ym6c3ez@snom190 [Jun 25 14:16:44] DEBUG[76060]: chan_sip.c:4702 sip_hangup: update_call_counter() - decrement call limit counter on hangup [Jun 25 14:16:44] DEBUG[76060]: chan_sip.c:4389 update_call_counter: Updating call counter for incoming call [Jun 25 14:16:44] DEBUG[76060]: chan_sip.c:4435 update_call_counter: Call from user '' removed from call limit 1 [Jun 25 14:16:44] DEBUG[76060]: chan_sip.c:3763 sip_destroy_user: Destroying user object from memory: [Jun 25 14:16:44] DEBUG[76060]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/-087f3000 [Jun 25 14:16:44] DEBUG[76060]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/ [Jun 25 14:16:44] DEBUG[76060]: cdr.c:1180 ast_cdr_detach: CDR detaching from this thread [Jun 25 14:16:44] DEBUG[76060]: chan_sip.c:3707 realtime_peer: -REALTIME- loading peer from database to memory. Name: CiscoAccount. Peer objects: 3 [Jun 25 14:16:44] DEBUG[76060]: chan_sip.c:3465 sip_destroy_peer: Destroying SIP peer CiscoAccount [Jun 25 14:16:44] DEBUG[76060]: chan_sip.c:3498 sip_destroy_peer: -REALTIME- peer Destroyed. Name: CiscoAccount. Realtime Peer objects: 2 [Jun 25 14:16:44] DEBUG[76060]: devicestate.c:430 do_state_change: Changing state for SIP/CiscoAccount - state 1 (Not in use) [Jun 25 14:16:44] DEBUG[76060]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for SIP - CiscoAccount [Jun 25 14:16:44] DEBUG[76060]: chan_sip.c:18961 sip_devicestate: Checking device state for peer CiscoAccount [Jun 25 14:16:44] DEBUG[76060]: app_queue.c:761 handle_statechange: Device 'SIP/CiscoAccount' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 25 14:16:44] DEBUG[76060]: devicestate.c:430 do_state_change: Changing state for SIP/CiscoAccount - state 1 (Not in use) [Jun 25 14:16:44] DEBUG[76060]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for SIP - CiscoAccount-087fe000 [Jun 25 14:16:44] DEBUG[76060]: chan_sip.c:18961 sip_devicestate: Checking device state for peer CiscoAccount-087fe000 [Jun 25 14:16:44] DEBUG[76060]: app_queue.c:761 handle_statechange: Device 'SIP/CiscoAccount' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 25 14:16:44] DEBUG[76060]: devicestate.c:430 do_state_change: Changing state for SIP/CiscoAccount-087fe000 - state 1 (Not in use) [Jun 25 14:16:44] DEBUG[76060]: app_queue.c:761 handle_statechange: Device 'SIP/CiscoAccount-087fe000' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 25 14:16:44] DEBUG[76060]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for SIP - CiscoAccount [Jun 25 14:16:44] DEBUG[76060]: chan_sip.c:18961 sip_devicestate: Checking device state for peer CiscoAccount [Jun 25 14:16:44] DEBUG[76060]: chan_sip.c:19750 build_peer: -REALTIME- peer built. Name: CiscoAccount. Peer objects: 3 Really destroying SIP dialog '3c2675ef6b6c-3y1w8ym6c3ez@snom190' Method: BYE [Jun 25 14:16:45] DEBUG[76060]: chan_sip.c:3707 realtime_peer: -REALTIME- loading peer from database to memory. Name: CiscoAccount. Peer objects: 3 [Jun 25 14:16:45] DEBUG[76060]: chan_sip.c:3465 sip_destroy_peer: Destroying SIP peer CiscoAccount [Jun 25 14:16:45] DEBUG[76060]: chan_sip.c:3498 sip_destroy_peer: -REALTIME- peer Destroyed. Name: CiscoAccount. Realtime Peer objects: 2 [Jun 25 14:16:45] DEBUG[76060]: devicestate.c:430 do_state_change: Changing state for SIP/CiscoAccount - state 1 (Not in use) [Jun 25 14:16:45] DEBUG[76060]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for SIP - SIPACCOUNT-087f3000 [Jun 25 14:16:45] DEBUG[76060]: chan_sip.c:18961 sip_devicestate: Checking device state for peer -087f3000 [Jun 25 14:16:45] DEBUG[76060]: app_queue.c:761 handle_statechange: Device 'SIP/CiscoAccount' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 25 14:16:45] DEBUG[76060]: devicestate.c:430 do_state_change: Changing state for SIP/-087f3000 - state 1 (Not in use) [Jun 25 14:16:45] DEBUG[76060]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for SIP - [Jun 25 14:16:45] DEBUG[76060]: chan_sip.c:18961 sip_devicestate: Checking device state for peer [Jun 25 14:16:45] DEBUG[76060]: app_queue.c:761 handle_statechange: Device 'SIP/-087f3000' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jun 25 14:16:45] DEBUG[76060]: chan_sip.c:19750 build_peer: -REALTIME- peer built. Name: . Peer objects: 3 [Jun 25 14:16:45] DEBUG[76060]: db.c:229 ast_db_del: Unable to find key '' in family 'SIP/Registry' [Jun 25 14:16:45] DEBUG[76060]: chan_sip.c:20041 build_peer: Bah, we're expired (16494/1214358111/1214374605)! [Jun 25 14:16:45] DEBUG[76060]: db.c:190 ast_db_get: Unable to find key '' in family 'SIP/Registry' [Jun 25 14:16:45] DEBUG[76060]: chan_sip.c:3707 realtime_peer: -REALTIME- loading peer from database to memory. Name: . Peer objects: 3 [Jun 25 14:16:45] DEBUG[76060]: chan_sip.c:3465 sip_destroy_peer: Destroying SIP peer [Jun 25 14:16:45] DEBUG[76060]: chan_sip.c:3498 sip_destroy_peer: -REALTIME- peer Destroyed. Name: . Realtime Peer objects: 2 [Jun 25 14:16:45] DEBUG[76060]: devicestate.c:430 do_state_change: Changing state for SIP/ - state 5 (Unavailable) [Jun 25 14:16:45] DEBUG[76060]: app_queue.c:761 handle_statechange: Device 'SIP/' changed to state '5' (Unavailable) but we don't care because they're not a member of any queue. voip01*CLI>