Apr 25 16:56:09 NOTICE[3080128176] cdr.c: CDR simple logging enabled. Apr 25 16:56:09 WARNING[3080128176] res_musiconhold.c: No music on hold classes configured, disabling music on hold. Apr 25 16:56:09 VERBOSE[3080128176] logger.c: CHAN FAX: Starting Fax Modem SLOT 0 Apr 25 16:56:09 VERBOSE[3080128176] logger.c: CHAN FAX: Starting Fax Modem SLOT 1 Apr 25 16:56:09 NOTICE[2988989344] faxmodem.c: Opened pty, slave device: /dev/pts/0 Apr 25 16:56:09 ERROR[2988989344] faxmodem.c: Fatal error: failed to create /dev/fax/0 symbolic link Apr 25 16:56:09 VERBOSE[2988989344] logger.c: CHAN FAX: Thread ended for /dev/fax/0 Apr 25 16:56:09 NOTICE[2988723104] faxmodem.c: Opened pty, slave device: /dev/pts/0 Apr 25 16:56:09 ERROR[2988723104] faxmodem.c: Fatal error: failed to create /dev/fax/1 symbolic link Apr 25 16:56:09 VERBOSE[2988723104] logger.c: CHAN FAX: Thread ended for /dev/fax/1 Apr 25 16:56:09 NOTICE[3080128176] app_nconference.c: Loading NConference module Apr 25 16:57:09 DEBUG[2988723104] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) Apr 25 16:57:09 DEBUG[2988723104] chan_sip.c: Header 0: OPTIONS sip:400@10.10.7.37 SIP/2.0 (34) Apr 25 16:57:09 DEBUG[2988723104] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.10.250.62:5060;branch=z9hG4bK5f5180c9 (57) Apr 25 16:57:09 DEBUG[2988723104] chan_sip.c: Header 2: From: "callweaver" ;tag=as39f10b81 (63) Apr 25 16:57:09 DEBUG[2988723104] chan_sip.c: Header 3: To: (24) Apr 25 16:57:09 DEBUG[2988723104] chan_sip.c: Header 4: Contact: (38) Apr 25 16:57:09 DEBUG[2988723104] chan_sip.c: Header 5: Call-ID: 53919d702b3abb0d435168587bf8ce08@10.10.250.62 (54) Apr 25 16:57:09 DEBUG[2988723104] chan_sip.c: Header 6: CSeq: 102 OPTIONS (17) Apr 25 16:57:09 DEBUG[2988723104] chan_sip.c: Header 7: User-Agent: CallWeaver (22) Apr 25 16:57:09 DEBUG[2988723104] chan_sip.c: Header 8: Max-Forwards: 70 (16) Apr 25 16:57:09 DEBUG[2988723104] chan_sip.c: Header 9: Date: Wed, 25 Apr 2007 20:57:09 GMT (35) Apr 25 16:57:09 DEBUG[2988723104] chan_sip.c: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) Apr 25 16:57:09 DEBUG[2988723104] chan_sip.c: Header 11: Content-Length: 0 (17) Apr 25 16:57:09 DEBUG[2988723104] chan_sip.c: Header 12: (0) Apr 25 16:57:09 VERBOSE[2988723104] logger.c: 12 headers, 0 lines Apr 25 16:57:09 VERBOSE[2988723104] logger.c: Reliably Transmitting (NAT) to 10.10.7.37:5060: OPTIONS sip:400@10.10.7.37 SIP/2.0 Via: SIP/2.0/UDP 10.10.250.62:5060;branch=z9hG4bK5f5180c9 From: "callweaver" ;tag=as39f10b81 To: Contact: Call-ID: 53919d702b3abb0d435168587bf8ce08@10.10.250.62 CSeq: 102 OPTIONS User-Agent: CallWeaver Max-Forwards: 70 Date: Wed, 25 Apr 2007 20:57:09 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Length: 0 --- Apr 25 16:57:09 DEBUG[2988723104] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #6 Apr 25 16:57:09 VERBOSE[2988723104] logger.c: <-- SIP read from 10.10.7.37:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.10.250.62:5060;branch=z9hG4bK5f5180c9 From: "callweaver" ;tag=as39f10b81 To: ;tag=87d6e961af9c79c2 Call-ID: 53919d702b3abb0d435168587bf8ce08@10.10.250.62 CSeq: 102 OPTIONS User-Agent: Grandstream HT386 1.0.3.64 FXS1 Contact: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Supported: replaces Content-Length: 0 Apr 25 16:57:09 DEBUG[2988723104] chan_sip.c: Header 0: SIP/2.0 200 OK (14) Apr 25 16:57:09 DEBUG[2988723104] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.10.250.62:5060;branch=z9hG4bK5f5180c9 (57) Apr 25 16:57:09 DEBUG[2988723104] chan_sip.c: Header 2: From: "callweaver" ;tag=as39f10b81 (63) Apr 25 16:57:09 DEBUG[2988723104] chan_sip.c: Header 3: To: ;tag=87d6e961af9c79c2 (45) Apr 25 16:57:09 DEBUG[2988723104] chan_sip.c: Header 4: Call-ID: 53919d702b3abb0d435168587bf8ce08@10.10.250.62 (54) Apr 25 16:57:09 DEBUG[2988723104] chan_sip.c: Header 5: CSeq: 102 OPTIONS (17) Apr 25 16:57:09 DEBUG[2988723104] chan_sip.c: Header 6: User-Agent: Grandstream HT386 1.0.3.64 FXS1 (43) Apr 25 16:57:09 DEBUG[2988723104] chan_sip.c: Header 7: Contact: (29) Apr 25 16:57:09 DEBUG[2988723104] chan_sip.c: Header 8: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE (64) Apr 25 16:57:09 DEBUG[2988723104] chan_sip.c: Header 9: Supported: replaces (19) Apr 25 16:57:09 DEBUG[2988723104] chan_sip.c: Header 10: Content-Length: 0 (17) Apr 25 16:57:09 DEBUG[2988723104] chan_sip.c: Header 11: (0) Apr 25 16:57:09 VERBOSE[2988723104] logger.c: --- (11 headers 0 lines) --- Apr 25 16:57:09 DEBUG[2988723104] chan_sip.c: = Found Their Call ID: 53919d702b3abb0d435168587bf8ce08@10.10.250.62 Their Tag Our tag: as39f10b81 Apr 25 16:57:09 DEBUG[2988723104] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #6 Apr 25 16:57:09 DEBUG[2988723104] chan_sip.c: Stopping retransmission on '53919d702b3abb0d435168587bf8ce08@10.10.250.62' of Request 102: Match Found Apr 25 16:57:09 VERBOSE[2988723104] logger.c: Destroying call '53919d702b3abb0d435168587bf8ce08@10.10.250.62' Apr 25 16:57:25 VERBOSE[2988723104] logger.c: <-- SIP read from 10.10.7.37:5060: INVITE sip:666@10.10.250.62 SIP/2.0 Via: SIP/2.0/UDP 10.10.7.37;branch=z9hG4bK493fec461f25c67b From: ;tag=40e2b4adca7ff28f To: Contact: Supported: replaces Call-ID: f66398437721a5ce@10.10.7.37 CSeq: 5257 INVITE User-Agent: Grandstream HT386 1.0.3.64 FXS1 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Content-Type: application/sdp Content-Length: 328 v=0 o=400 8000 8000 IN IP4 10.10.7.37 s=SIP Call c=IN IP4 10.10.7.37 t=0 0 m=audio 5008 RTP/AVP 0 18 4 2 97 101 a=sendrecv a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=rtpmap:4 G723/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:97 iLBC/8000 a=fmtp:97 mode=20 a=ptime:20 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11 Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 0: INVITE sip:666@10.10.250.62 SIP/2.0 (35) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.10.7.37;branch=z9hG4bK493fec461f25c67b (58) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 2: From: ;tag=40e2b4adca7ff28f (49) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 3: To: (26) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 4: Contact: (29) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 5: Supported: replaces (19) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 6: Call-ID: f66398437721a5ce@10.10.7.37 (36) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 7: CSeq: 5257 INVITE (17) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 8: User-Agent: Grandstream HT386 1.0.3.64 FXS1 (43) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 9: Max-Forwards: 70 (16) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 10: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE (64) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 11: Content-Type: application/sdp (29) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 12: Content-Length: 328 (19) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 13: (0) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Line: v=0 (3) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Line: o=400 8000 8000 IN IP4 10.10.7.37 (33) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Line: s=SIP Call (10) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Line: c=IN IP4 10.10.7.37 (19) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Line: t=0 0 (5) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Line: m=audio 5008 RTP/AVP 0 18 4 2 97 101 (36) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Line: a=sendrecv (10) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Line: a=rtpmap:18 G729/8000 (21) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Line: a=rtpmap:4 G723/8000 (20) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Line: a=rtpmap:2 G726-32/8000 (23) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Line: a=rtpmap:97 iLBC/8000 (21) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Line: a=fmtp:97 mode=20 (17) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Line: a=ptime:20 (10) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Line: a=fmtp:101 0-11 (15) Apr 25 16:57:25 VERBOSE[2988723104] logger.c: --- (13 headers 16 lines) --- Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Allocating new SIP dialog for f66398437721a5ce@10.10.7.37 - INVITE (With RTP) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Begin: parsing SIP "Supported: replaces" Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Found SIP option: -replaces- Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Matched SIP option: replaces Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: * SIP extension value: 1 for call f66398437721a5ce@10.10.7.37 Apr 25 16:57:25 VERBOSE[2988723104] logger.c: Using INVITE request as basis request - f66398437721a5ce@10.10.7.37 Apr 25 16:57:25 VERBOSE[2988723104] logger.c: Sending to 10.10.7.37 : 5060 (NAT) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: *** Setting NAT on RTP to 1 Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Setting NAT on UDPTL to 1 Apr 25 16:57:25 VERBOSE[2988723104] logger.c: Reliably Transmitting (NAT) to 10.10.7.37:5060: SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 10.10.7.37;branch=z9hG4bK493fec461f25c67b;received=10.10.7.37 From: ;tag=40e2b4adca7ff28f To: ;tag=as1cd8a96e Call-ID: f66398437721a5ce@10.10.7.37 CSeq: 5257 INVITE User-Agent: CallWeaver Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Max-Forwards: 70 WWW-Authenticate: Digest algorithm=MD5, realm="callweaver.org", nonce="3814410f" Content-Length: 0 --- Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #9 Apr 25 16:57:25 VERBOSE[2988723104] logger.c: Scheduling destruction of call 'f66398437721a5ce@10.10.7.37' in 15000 ms Apr 25 16:57:25 VERBOSE[2988723104] logger.c: Found user '400' Apr 25 16:57:25 VERBOSE[2988723104] logger.c: <-- SIP read from 10.10.7.37:5060: ACK sip:666@10.10.250.62 SIP/2.0 Via: SIP/2.0/UDP 10.10.7.37;branch=z9hG4bK493fec461f25c67b From: ;tag=40e2b4adca7ff28f To: ;tag=as1cd8a96e Contact: Call-ID: f66398437721a5ce@10.10.7.37 CSeq: 5257 ACK User-Agent: Grandstream HT386 1.0.3.64 FXS1 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Content-Length: 0 Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 0: ACK sip:666@10.10.250.62 SIP/2.0 (32) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.10.7.37;branch=z9hG4bK493fec461f25c67b (58) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 2: From: ;tag=40e2b4adca7ff28f (49) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 3: To: ;tag=as1cd8a96e (41) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 4: Contact: (29) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 5: Call-ID: f66398437721a5ce@10.10.7.37 (36) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 6: CSeq: 5257 ACK (14) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 7: User-Agent: Grandstream HT386 1.0.3.64 FXS1 (43) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 8: Max-Forwards: 70 (16) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 9: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE (64) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 10: Content-Length: 0 (17) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 11: (0) Apr 25 16:57:25 VERBOSE[2988723104] logger.c: --- (11 headers 0 lines) --- Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: = Found Their Call ID: f66398437721a5ce@10.10.7.37 Their Tag 40e2b4adca7ff28f Our tag: as1cd8a96e Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: **** Received ACK (6) - Command in SIP ACK Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #9 Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Stopping retransmission on 'f66398437721a5ce@10.10.7.37' of Response 5257: Match Found Apr 25 16:57:25 VERBOSE[2988723104] logger.c: <-- SIP read from 10.10.7.37:5060: INVITE sip:666@10.10.250.62 SIP/2.0 Via: SIP/2.0/UDP 10.10.7.37;branch=z9hG4bK5ad6166f33a595a5 From: ;tag=40e2b4adca7ff28f To: Contact: Supported: replaces Authorization: Digest username="400", realm="callweaver.org", algorithm=MD5, uri="sip:666@10.10.250.62", nonce="3814410f", response="a80d5c9686cf6a4ff9463c5f644a8cd9" Call-ID: f66398437721a5ce@10.10.7.37 CSeq: 5258 INVITE User-Agent: Grandstream HT386 1.0.3.64 FXS1 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Content-Type: application/sdp Content-Length: 328 v=0 o=400 8000 8001 IN IP4 10.10.7.37 s=SIP Call c=IN IP4 10.10.7.37 t=0 0 m=audio 5008 RTP/AVP 0 18 4 2 97 101 a=sendrecv a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=rtpmap:4 G723/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:97 iLBC/8000 a=fmtp:97 mode=20 a=ptime:20 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11 Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 0: INVITE sip:666@10.10.250.62 SIP/2.0 (35) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.10.7.37;branch=z9hG4bK5ad6166f33a595a5 (58) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 2: From: ;tag=40e2b4adca7ff28f (49) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 3: To: (26) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 4: Contact: (29) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 5: Supported: replaces (19) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 6: Authorization: Digest username="400", realm="callweaver.org", algorithm=MD5, uri="sip:666@10.10.250.62", nonce="3814410f", response="a80d5c9686cf6a4ff9463c5f644a8cd9" (166) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 7: Call-ID: f66398437721a5ce@10.10.7.37 (36) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 8: CSeq: 5258 INVITE (17) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 9: User-Agent: Grandstream HT386 1.0.3.64 FXS1 (43) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 10: Max-Forwards: 70 (16) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 11: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE (64) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 12: Content-Type: application/sdp (29) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 13: Content-Length: 328 (19) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 14: (0) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Line: v=0 (3) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Line: o=400 8000 8001 IN IP4 10.10.7.37 (33) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Line: s=SIP Call (10) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Line: c=IN IP4 10.10.7.37 (19) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Line: t=0 0 (5) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Line: m=audio 5008 RTP/AVP 0 18 4 2 97 101 (36) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Line: a=sendrecv (10) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Line: a=rtpmap:18 G729/8000 (21) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Line: a=rtpmap:4 G723/8000 (20) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Line: a=rtpmap:2 G726-32/8000 (23) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Line: a=rtpmap:97 iLBC/8000 (21) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Line: a=fmtp:97 mode=20 (17) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Line: a=ptime:20 (10) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Line: a=fmtp:101 0-11 (15) Apr 25 16:57:25 VERBOSE[2988723104] logger.c: --- (14 headers 16 lines) --- Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: = Found Their Call ID: f66398437721a5ce@10.10.7.37 Their Tag 40e2b4adca7ff28f Our tag: as1cd8a96e Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE Apr 25 16:57:25 VERBOSE[2988723104] logger.c: Using INVITE request as basis request - f66398437721a5ce@10.10.7.37 Apr 25 16:57:25 VERBOSE[2988723104] logger.c: Sending to 10.10.7.37 : 5060 (NAT) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: *** Setting NAT on RTP to 1 Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Setting NAT on UDPTL to 1 Apr 25 16:57:25 VERBOSE[2988723104] logger.c: Found user '400' Apr 25 16:57:25 VERBOSE[2988723104] logger.c: Found RTP audio format 0 Apr 25 16:57:25 VERBOSE[2988723104] logger.c: Found RTP audio format 18 Apr 25 16:57:25 VERBOSE[2988723104] logger.c: Found RTP audio format 4 Apr 25 16:57:25 VERBOSE[2988723104] logger.c: Found RTP audio format 2 Apr 25 16:57:25 VERBOSE[2988723104] logger.c: Found RTP audio format 97 Apr 25 16:57:25 VERBOSE[2988723104] logger.c: Found RTP audio format 101 Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Activating RTP on response f66398437721a5ce@10.10.7.37 (1) Apr 25 16:57:25 VERBOSE[2988723104] logger.c: Peer audio RTP is at port 10.10.7.37:5008 Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Peer audio RTP is at port 10.10.7.37:5008 Apr 25 16:57:25 VERBOSE[2988723104] logger.c: Found description format PCMU Apr 25 16:57:25 VERBOSE[2988723104] logger.c: Found description format G729 Apr 25 16:57:25 VERBOSE[2988723104] logger.c: Found description format G723 Apr 25 16:57:25 VERBOSE[2988723104] logger.c: Found description format G726-32 Apr 25 16:57:25 VERBOSE[2988723104] logger.c: Found description format iLBC Apr 25 16:57:25 VERBOSE[2988723104] logger.c: Found description format telephone-event Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: T38 state changed to 0 on channel Apr 25 16:57:25 VERBOSE[2988723104] logger.c: Capabilities: us - 0x8000e (gsm|ulaw|alaw|h263), peer - audio=0x515 (g723|ulaw|g726|g729|ilbc)/video=0x0 (nothing), combined - 0x4 (ulaw) Apr 25 16:57:25 VERBOSE[2988723104] logger.c: Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Checking SIP call limits for device 400 Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Updating call counter for incoming call Apr 25 16:57:25 VERBOSE[2988723104] logger.c: Looking for 666 in inbound (domain 10.10.250.62) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: build_route: Contact hop: Apr 25 16:57:25 VERBOSE[2988723104] logger.c: list_route: hop: Apr 25 16:57:25 VERBOSE[2988723104] logger.c: Transmitting (NAT) to 10.10.7.37:5060: SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.10.7.37;branch=z9hG4bK5ad6166f33a595a5;received=10.10.7.37 From: ;tag=40e2b4adca7ff28f To: Call-ID: f66398437721a5ce@10.10.7.37 CSeq: 5258 INVITE User-Agent: CallWeaver Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Max-Forwards: 70 Contact: Content-Length: 0 --- Apr 25 16:57:25 DEBUG[3079719840] chan_sip.c: Checking device state for peer 400 Apr 25 16:57:25 DEBUG[3079719840] devicestate.c: Changing state for SIP/400 - state 2 (In use) Apr 25 16:57:25 DEBUG[2983607200] pbx.c: Launching 'Goto' Apr 25 16:57:25 VERBOSE[2983607200] logger.c: -- Executing Goto("SIP/400-66a0", "sipfax|s|1") in new stack Apr 25 16:57:25 VERBOSE[2983607200] logger.c: -- Goto (sipfax,s,1) Apr 25 16:57:25 DEBUG[2983607200] pbx.c: Launching 'Set' Apr 25 16:57:25 VERBOSE[2983607200] logger.c: -- Executing Set("SIP/400-66a0", "LOCALSTATIONID=Navynet.it FAX") in new stack Apr 25 16:57:25 DEBUG[2983607200] pbx.c: Launching 'Set' Apr 25 16:57:25 VERBOSE[2983607200] logger.c: -- Executing Set("SIP/400-66a0", "LOCALHEADERINFO=Navynet SRL is a solution provider for business") in new stack Apr 25 16:57:25 DEBUG[2983607200] pbx.c: Launching 'Set' Apr 25 16:57:25 VERBOSE[2983607200] logger.c: -- Executing Set("SIP/400-66a0", "FAXFILE=/opt/tmp/fax.tif") in new stack Apr 25 16:57:25 DEBUG[2983607200] pbx.c: Launching 'Set' Apr 25 16:57:25 VERBOSE[2983607200] logger.c: -- Executing Set("SIP/400-66a0", "FAXFILENOEXT=/opt/tmp/fax") in new stack Apr 25 16:57:25 DEBUG[2983607200] pbx.c: Launching 'FaxDetect' Apr 25 16:57:25 VERBOSE[2983607200] logger.c: -- Executing FaxDetect("SIP/400-66a0", "4000") in new stack Apr 25 16:57:25 DEBUG[2983607200] app_faxdetect.c: Preparing detect of fax (waitdur=4000ms, sildur=1000ms, mindur=100ms, maxdur=-1ms) Apr 25 16:57:25 DEBUG[3079719840] chan_sip.c: Checking device state for peer 400 Apr 25 16:57:25 DEBUG[3079719840] channel.c: Avoiding initial deadlock for 'SIP/400-66a0' Apr 25 16:57:25 DEBUG[2983607200] chan_sip.c: sip_answer(SIP/400-66a0) Apr 25 16:57:25 VERBOSE[2983607200] logger.c: We're at 10.10.250.62 port 11564 Apr 25 16:57:25 VERBOSE[2983607200] logger.c: Adding codec 0x4 (ulaw) to SDP Apr 25 16:57:25 VERBOSE[2983607200] logger.c: Adding codec 0x2 (gsm) to SDP Apr 25 16:57:25 VERBOSE[2983607200] logger.c: Adding codec 0x8 (alaw) to SDP Apr 25 16:57:25 VERBOSE[2983607200] logger.c: Adding non-codec 0x1 (telephone-event) to SDP Apr 25 16:57:25 VERBOSE[2983607200] logger.c: Reliably Transmitting (NAT) to 10.10.7.37:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.10.7.37;branch=z9hG4bK5ad6166f33a595a5;received=10.10.7.37 From: ;tag=40e2b4adca7ff28f To: ;tag=as73a4778b Call-ID: f66398437721a5ce@10.10.7.37 CSeq: 5258 INVITE User-Agent: CallWeaver Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Max-Forwards: 70 Contact: Content-Type: application/sdp Content-Length: 263 v=0 o=root 23771 23771 IN IP4 10.10.250.62 s=session c=IN IP4 10.10.250.62 t=0 0 m=audio 11564 RTP/AVP 0 3 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - --- Apr 25 16:57:25 DEBUG[2983607200] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #11 Apr 25 16:57:25 DEBUG[2983607200] channel.c: Set channel SIP/400-66a0 to read format slin Apr 25 16:57:25 DEBUG[2983607200] channel.c: Set channel SIP/400-66a0 to write format slin Apr 25 16:57:25 DEBUG[2983340960] app_queue.c: Device 'SIP/400' changed to state '2' (In use) Apr 25 16:57:25 VERBOSE[2988723104] logger.c: <-- SIP read from 10.10.7.37:5060: ACK sip:666@10.10.250.62 SIP/2.0 Via: SIP/2.0/UDP 10.10.7.37;branch=z9hG4bK5286369c13a02805 From: ;tag=40e2b4adca7ff28f To: ;tag=as73a4778b Contact: Authorization: Digest username="400", realm="callweaver.org", algorithm=MD5, uri="sip:666@10.10.250.62", nonce="3814410f", response="e0b77cddaa74266cbfc42425fe15768d" Call-ID: f66398437721a5ce@10.10.7.37 CSeq: 5258 ACK User-Agent: Grandstream HT386 1.0.3.64 FXS1 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Content-Length: 0 Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 0: ACK sip:666@10.10.250.62 SIP/2.0 (32) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.10.7.37;branch=z9hG4bK5286369c13a02805 (58) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 2: From: ;tag=40e2b4adca7ff28f (49) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 3: To: ;tag=as73a4778b (41) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 4: Contact: (29) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 5: Authorization: Digest username="400", realm="callweaver.org", algorithm=MD5, uri="sip:666@10.10.250.62", nonce="3814410f", response="e0b77cddaa74266cbfc42425fe15768d" (166) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 6: Call-ID: f66398437721a5ce@10.10.7.37 (36) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 7: CSeq: 5258 ACK (14) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 8: User-Agent: Grandstream HT386 1.0.3.64 FXS1 (43) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 9: Max-Forwards: 70 (16) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 10: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE (64) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 11: Content-Length: 0 (17) Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Header 12: (0) Apr 25 16:57:25 VERBOSE[2988723104] logger.c: --- (12 headers 0 lines) --- Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: = Found Their Call ID: f66398437721a5ce@10.10.7.37 Their Tag 40e2b4adca7ff28f Our tag: as73a4778b Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: **** Received ACK (6) - Command in SIP ACK Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #11 Apr 25 16:57:25 DEBUG[2988723104] chan_sip.c: Stopping retransmission on 'f66398437721a5ce@10.10.7.37' of Response 5258: Match Found Apr 25 16:57:25 DEBUG[3079719840] devicestate.c: Changing state for SIP/400 - state 2 (In use) Apr 25 16:57:25 DEBUG[2983340960] app_queue.c: Device 'SIP/400' changed to state '2' (In use) Apr 25 16:57:25 DEBUG[2983607200] rtp.c: Ooh, format changed from unknown to ulaw Apr 25 16:57:25 DEBUG[2983607200] rtp.c: Had to change frame MS from 0 to 20 Apr 25 16:57:25 DEBUG[2983607200] rtp.c: Able to create smoother :) ms: 20 len 160 Apr 25 16:57:27 DEBUG[2983607200] app_faxdetect.c: Start of voice token Apr 25 16:57:27 DEBUG[2983607200] app_faxdetect.c: Fax detected on SIP/400-66a0 Apr 25 16:57:27 NOTICE[2983607200] app_faxdetect.c: Redirecting SIP/400-66a0 to fax extension [DTMF] Apr 25 16:57:27 DEBUG[2983607200] channel.c: Set channel SIP/400-66a0 to read format ulaw Apr 25 16:57:27 DEBUG[2983607200] channel.c: Set channel SIP/400-66a0 to write format ulaw Apr 25 16:57:27 DEBUG[2983607200] pbx.c: Launching 'SipT38SwitchOver' Apr 25 16:57:27 VERBOSE[2983607200] logger.c: -- Executing SipT38SwitchOver("SIP/400-66a0", "") in new stack Apr 25 16:57:27 DEBUG[2983607200] chan_sip.c: Forcing reinvite on SIP (SIP/400-66a0) for T.38 negotiation. Apr 25 16:57:27 VERBOSE[2983607200] logger.c: set_destination: Parsing for address/port to send to Apr 25 16:57:27 VERBOSE[2983607200] logger.c: set_destination: set destination to 10.10.7.37, port 5060 Apr 25 16:57:27 VERBOSE[2983607200] logger.c: T.38 UDPTL is at port 10.10.250.62:11564 Apr 25 16:57:27 DEBUG[2983607200] chan_sip.c: Our T38 capability (12048), peer T38 capability (0), joint capability (12048) Apr 25 16:57:27 DEBUG[2983607200] chan_sip.c: T38MaxFaxRate 14400 found Apr 25 16:57:27 DEBUG[2983607200] chan_sip.c: Header 0: INVITE sip:400@10.10.7.37 SIP/2.0 (33) Apr 25 16:57:27 DEBUG[2983607200] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.10.250.62:5060;branch=z9hG4bK3e672f4e (57) Apr 25 16:57:27 DEBUG[2983607200] chan_sip.c: Header 2: From: ;tag=as73a4778b (43) Apr 25 16:57:27 DEBUG[2983607200] chan_sip.c: Header 3: To: ;tag=40e2b4adca7ff28f (47) Apr 25 16:57:27 DEBUG[2983607200] chan_sip.c: Header 4: Contact: (31) Apr 25 16:57:27 DEBUG[2983607200] chan_sip.c: Header 5: Call-ID: f66398437721a5ce@10.10.7.37 (36) Apr 25 16:57:27 DEBUG[2983607200] chan_sip.c: Header 6: CSeq: 102 INVITE (16) Apr 25 16:57:27 DEBUG[2983607200] chan_sip.c: Header 7: User-Agent: CallWeaver (22) Apr 25 16:57:27 DEBUG[2983607200] chan_sip.c: Header 8: Max-Forwards: 70 (16) Apr 25 16:57:27 DEBUG[2983607200] chan_sip.c: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) Apr 25 16:57:27 DEBUG[2983607200] chan_sip.c: Header 10: X-callweaver-info: SIP re-invite (T38 switchover) (49) Apr 25 16:57:27 DEBUG[2983607200] chan_sip.c: Header 11: Content-Type: application/sdp (29) Apr 25 16:57:27 DEBUG[2983607200] chan_sip.c: Header 12: Content-Length: 0 (17) Apr 25 16:57:27 DEBUG[2983607200] chan_sip.c: Header 13: (0) Apr 25 16:57:27 DEBUG[2983607200] chan_sip.c: Line: v=0 (3) Apr 25 16:57:27 DEBUG[2983607200] chan_sip.c: Line: o=root 23771 23772 IN IP4 10.10.250.62 (38) Apr 25 16:57:27 DEBUG[2983607200] chan_sip.c: Line: s=session (9) Apr 25 16:57:27 DEBUG[2983607200] chan_sip.c: Line: c=IN IP4 10.10.250.62 (21) Apr 25 16:57:27 DEBUG[2983607200] chan_sip.c: Line: t=0 0 (5) Apr 25 16:57:27 DEBUG[2983607200] chan_sip.c: Line: m=image 11564 udptl t38 (23) Apr 25 16:57:27 DEBUG[2983607200] chan_sip.c: Line: a=T38FaxVersion:0 (17) Apr 25 16:57:27 DEBUG[2983607200] chan_sip.c: Line: a=T38MaxBitRate:14400 (21) Apr 25 16:57:27 DEBUG[2983607200] chan_sip.c: Line: a=T38FaxFillBitRemoval:0 (24) Apr 25 16:57:27 DEBUG[2983607200] chan_sip.c: Line: a=T38FaxTranscodingMMR:0 (24) Apr 25 16:57:27 DEBUG[2983607200] chan_sip.c: Line: a=T38FaxTranscodingJBIG:0 (25) Apr 25 16:57:27 DEBUG[2983607200] chan_sip.c: Line: a=T38FaxRateManagement:transferredTCF (37) Apr 25 16:57:27 DEBUG[2983607200] chan_sip.c: Line: a=T38FaxMaxBuffer:400 (21) Apr 25 16:57:27 DEBUG[2983607200] chan_sip.c: Line: a=T38FaxMaxDatagram:400 (23) Apr 25 16:57:27 DEBUG[2983607200] chan_sip.c: Line: a=T38FaxUdpEC:t38UDPFEC (23) Apr 25 16:57:27 VERBOSE[2983607200] logger.c: 13 headers, 15 lines Apr 25 16:57:27 VERBOSE[2983607200] logger.c: Reliably Transmitting (NAT) to 10.10.7.37:5060: INVITE sip:400@10.10.7.37 SIP/2.0 Via: SIP/2.0/UDP 10.10.250.62:5060;branch=z9hG4bK3e672f4e From: ;tag=as73a4778b To: ;tag=40e2b4adca7ff28f Contact: Call-ID: f66398437721a5ce@10.10.7.37 CSeq: 102 INVITE User-Agent: CallWeaver Max-Forwards: 70 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY X-callweaver-info: SIP re-invite (T38 switchover) Content-Type: application/sdp Content-Length: 344 v=0 o=root 23771 23772 IN IP4 10.10.250.62 s=session c=IN IP4 10.10.250.62 t=0 0 m=image 11564 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:14400 a=T38FaxFillBitRemoval:0 a=T38FaxTranscodingMMR:0 a=T38FaxTranscodingJBIG:0 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:400 a=T38FaxMaxDatagram:400 a=T38FaxUdpEC:t38UDPFEC --- Apr 25 16:57:27 DEBUG[2983607200] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #12 Apr 25 16:57:27 DEBUG[2983607200] chan_sip.c: T38 state changed to 2 on channel SIP/400-66a0 Apr 25 16:57:27 DEBUG[2983607200] pbx.c: Launching 'RxFAX' Apr 25 16:57:27 VERBOSE[2983607200] logger.c: -- Executing RxFAX("SIP/400-66a0", "(/opt/tmp/fax.tif|debug|ecm") in new stack Apr 25 16:57:27 DEBUG[2983607200] channel.c: Set channel SIP/400-66a0 to read format slin Apr 25 16:57:27 DEBUG[2983607200] channel.c: Set channel SIP/400-66a0 to write format slin Apr 25 16:57:28 DEBUG[2983607200] app_rxfax.c: Enabling ECM mode for app_rxfax Apr 25 16:57:28 NOTICE[2983607200] channel.c: Dropping incompatible voice frame on SIP/400-66a0 of format slin since our native format has changed to ulaw Apr 25 16:57:28 VERBOSE[2988723104] logger.c: <-- SIP read from 10.10.7.37:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.10.250.62:5060;branch=z9hG4bK3e672f4e From: ;tag=as73a4778b To: ;tag=40e2b4adca7ff28f Call-ID: f66398437721a5ce@10.10.7.37 CSeq: 102 INVITE User-Agent: Grandstream HT386 1.0.3.64 FXS1 Contact: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Content-Type: application/sdp Supported: replaces Content-Length: 336 v=0 o=400 8000 8002 IN IP4 10.10.7.37 s=SIP Call c=IN IP4 10.10.7.37 t=0 0 m=image 5008 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:9600 a=T38FaxFillBitRemoval:0 a=T38FaxTranscodingMMR:0 a=T38FaxTranscodingJBIG:0 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:400 a=T38FaxMaxDatagram:400 a=T38FaxUdpEC:t38UDPFEC Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: Header 0: SIP/2.0 200 OK (14) Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.10.250.62:5060;branch=z9hG4bK3e672f4e (57) Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: Header 2: From: ;tag=as73a4778b (43) Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: Header 3: To: ;tag=40e2b4adca7ff28f (47) Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: Header 4: Call-ID: f66398437721a5ce@10.10.7.37 (36) Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: Header 5: CSeq: 102 INVITE (16) Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: Header 6: User-Agent: Grandstream HT386 1.0.3.64 FXS1 (43) Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: Header 7: Contact: (29) Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: Header 8: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE (64) Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: Header 9: Content-Type: application/sdp (29) Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: Header 10: Supported: replaces (19) Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: Header 11: Content-Length: 336 (19) Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: Header 12: (0) Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: Line: v=0 (3) Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: Line: o=400 8000 8002 IN IP4 10.10.7.37 (33) Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: Line: s=SIP Call (10) Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: Line: c=IN IP4 10.10.7.37 (19) Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: Line: t=0 0 (5) Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: Line: m=image 5008 udptl t38 (22) Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: Line: a=T38FaxVersion:0 (17) Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: Line: a=T38MaxBitRate:9600 (20) Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: Line: a=T38FaxFillBitRemoval:0 (24) Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: Line: a=T38FaxTranscodingMMR:0 (24) Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: Line: a=T38FaxTranscodingJBIG:0 (25) Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: Line: a=T38FaxRateManagement:transferredTCF (37) Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: Line: a=T38FaxMaxBuffer:400 (21) Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: Line: a=T38FaxMaxDatagram:400 (23) Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: Line: a=T38FaxUdpEC:t38UDPFEC (23) Apr 25 16:57:28 VERBOSE[2988723104] logger.c: --- (12 headers 15 lines) --- Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: = Found Their Call ID: f66398437721a5ce@10.10.7.37 Their Tag 40e2b4adca7ff28f Our tag: as73a4778b Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: Acked pending invite 102 Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #12 Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: Stopping retransmission on 'f66398437721a5ce@10.10.7.37' of Request 102: Match Found Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: SIP response 200 to RE-invite on outgoing call f66398437721a5ce@10.10.7.37 Apr 25 16:57:28 VERBOSE[2988723104] logger.c: Got T.38 offer in SDP Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: Activating UDPTL on response f66398437721a5ce@10.10.7.37 (1) Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: T38 state changed to 4 on channel SIP/400-66a0 Apr 25 16:57:28 VERBOSE[2988723104] logger.c: Peer T.38 UDPTL is at port 10.10.7.37:5008 Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: Peer T.38 UDPTL is at port 10.10.7.37:5008 Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: FaxVersion: 0 Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: T38MaxBitRate: 9600 Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: FillBitRemoval: 0 Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: Transcoding MMR: 0 Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: Transcoding JBIG: 0 Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: RateMangement: transferredTCF Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: MaxBufferSize:400 Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: FaxMaxDatagram: 400 Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: UDP EC: t38UDPFEC Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: Our T38 capability = (12048), peer T38 capability (3856), joint T38 capability (3856) Apr 25 16:57:28 VERBOSE[2988723104] logger.c: Capabilities: us - 0x8000e (gsm|ulaw|alaw|h263), peer - audio=0x515 (g723|ulaw|g726|g729|ilbc)/video=0x0 (nothing), combined - 0x4 (ulaw) Apr 25 16:57:28 VERBOSE[2988723104] logger.c: Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: build_route: Contact hop: Apr 25 16:57:28 VERBOSE[2988723104] logger.c: list_route: hop: Apr 25 16:57:28 DEBUG[2988723104] chan_sip.c: Channel Bridge information is non-existant. T38 Termination requested. Apr 25 16:57:28 VERBOSE[2988723104] logger.c: set_destination: Parsing for address/port to send to Apr 25 16:57:28 VERBOSE[2988723104] logger.c: set_destination: set destination to 10.10.7.37, port 5060 Apr 25 16:57:28 VERBOSE[2988723104] logger.c: Transmitting (NAT) to 10.10.7.37:5060: ACK sip:400@10.10.7.37 SIP/2.0 Via: SIP/2.0/UDP 10.10.250.62:5060;branch=z9hG4bK61e9625f From: ;tag=as73a4778b To: ;tag=40e2b4adca7ff28f Contact: Call-ID: f66398437721a5ce@10.10.7.37 CSeq: 102 ACK User-Agent: CallWeaver Max-Forwards: 70 Content-Length: 0 --- Apr 25 16:57:28 DEBUG[2983607200] app_rxfax.c: Enabling ECM mode for app_rxfax Apr 25 16:57:28 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 0: indicator no-signal Apr 25 16:57:28 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 0, len 8) Apr 25 16:57:28 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 10) Apr 25 16:57:28 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 0: 00 Apr 25 16:57:28 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 0: indicator no-signal Apr 25 16:57:28 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 10) Apr 25 16:57:28 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 0: 00 Apr 25 16:57:28 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 0: Repeat packet number Apr 25 16:57:28 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 10) Apr 25 16:57:28 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 0: 00 Apr 25 16:57:28 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 0: Repeat packet number Apr 25 16:57:28 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 1: indicator ced Apr 25 16:57:28 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 1, len 8) Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Send complete in phase T30_PHASE_A_CED, state 1 Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Starting answer mode Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Changing from phase T30_PHASE_A_CED to T30_PHASE_B_TX Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.38T Set rx type 0 Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.38T Set tx type 4 Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 DIS: Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... ...1= Store and forward Internet fax (T.37): Set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... .1..= Real-time Internet fax (T.38): Set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... 0...= 3G mobile network: Not set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 ..0. ....= V.8 capabilities: Not set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .0.. ....= Preferred octets: 256 octets Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... ...0= Ready to transmit a fax document (polling): Not set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... ..0.= Can receive fax: Not set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 ..10 11..= Supported data signalling rates: V.27 ter, V.29, and V.17 Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .1.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 1... ....= 2-D coding: Set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... ..10= Recording width: 215 mm +- 1-0x1.38f28b7e86f08p-226nd 255 mm +- 1 0x0.00005b7e0d57fp-1022nd 303 mm +- 1% Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... 10..= Recording length: Unlimited Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .111 ....= Receiver's minimum scan line time: 0 ms at 3.85 l/mm: T7.7 = T3.85 Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 1... ....= Extension indicator: Set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... ..0.= Compressed/uncompressed mode: Compressed Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... .1..= Error correction mode (ECM): ECM Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .1.. ....= T.6 coding: Set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 1... ....= Extension indicator: Set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... ...0= "Field not valid" supported: Not set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... ..0.= Multiple selective polling: Not set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... .0..= Polled subaddress: Not set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... 0...= T.43 coding: Not set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 ...0 ....= Plane interleave: Not set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 ..0. ....= Voice coding with 32kbit/s ADPCM (Rec. G.726): Not set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .0.. ....= Reserved for the use of extended voice coding set: Not set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 1... ....= Extension indicator: Set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... ...1= R8x15.4lines/mm: Set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... ..0.= 300x300pels/25.4mm: Not set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... .1..= R16x15.4lines/mm and/or 400x400pels/25.4 mm: Set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... 1...= Inch-based resolution preferred: Set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 ...0 ....= Metric-based resolution preferred: Not set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 ..0. ....= Minimum scan line time for higher resolutions: T15.4 = T7.7 Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .0.. ....= Selective polling: Not set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 1... ....= Extension indicator: Set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... ...0= Subaddressing: Not set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... ..0.= Password: Not set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... .0..= Ready to transmit a data file (polling): Not set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 ...0 ....= Binary file transfer (BFT): Not set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 ..0. ....= Document transfer mode (DTM): Not set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .0.. ....= Electronic data interchange (EDI): Not set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 1... ....= Extension indicator: Set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... ...0= Basic transfer mode (BTM): Not set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... .0..= Ready to transfer a character or mixed mode document (polling): Not set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... 0...= Character mode: Not set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 ..0. ....= Mixed mode (Annex E/T.4): Not set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 1... ....= Extension indicator: Set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... ...0= Processable mode 26 (Rec. T.505): Not set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... ..0.= Digital network capability: Not set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... .0..= Duplex capability: Half only Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... 0...= JPEG coding: Not set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 ...0 ....= Full colour mode: Not set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .0.. ....= 12bits/pel component: Not set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 1... ....= Extension indicator: Set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... ...0= No subsampling (1:1:1): Not set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... ..0.= Custom illuminant: Not set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... .0..= Custom gamut range: Not set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... 1...= North American Letter (215.9mm x 279.4mm): Set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 ...1 ....= North American Legal (215.9mm x 355.6mm): Set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 ..0. ....= Single-progression sequential coding (Rec. T.85) basic: Not set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .0.. ....= Single-progression sequential coding (Rec. T.85) optional L0: Not set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 0... ....= Extension indicator: Not set Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Changing from state 1 to 15 Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Sending ident 'Navynet.it FAX' Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Tx: CSI without final frame tag Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Tx: ff 03 40 58 41 46 20 74 69 2e 74 65 6e 79 76 61 4e 20 20 20 20 20 20 Apr 25 16:57:31 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 2: indicator v21-preamble Apr 25 16:57:31 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 2, len 8) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 3: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 3: c0 01 80 00 00 ff Apr 25 16:57:32 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 3, len 15) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 4: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 4: c0 01 80 00 00 c0 Apr 25 16:57:32 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 4, len 20) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 5: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 5: c0 01 80 00 00 02 Apr 25 16:57:32 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 5, len 20) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 6: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 6: c0 01 80 00 00 1a Apr 25 16:57:32 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 6, len 27) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 7: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 7: c0 01 80 00 00 82 Apr 25 16:57:32 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 7, len 27) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 8: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 8: c0 01 80 00 00 62 Apr 25 16:57:32 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 8, len 27) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 9: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 9: c0 01 80 00 00 04 Apr 25 16:57:32 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 9, len 34) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 10: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 10: c0 01 80 00 00 2e Apr 25 16:57:32 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 10, len 34) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 11: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 11: c0 01 80 00 00 96 Apr 25 16:57:32 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 11, len 34) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 12: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 12: c0 01 80 00 00 74 Apr 25 16:57:32 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 12, len 34) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 13: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 13: c0 01 80 00 00 2e Apr 25 16:57:32 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 13, len 34) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 14: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 14: c0 01 80 00 00 a6 Apr 25 16:57:32 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 14, len 34) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 15: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 15: c0 01 80 00 00 76 Apr 25 16:57:32 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 15, len 34) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 16: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 16: c0 01 80 00 00 9e Apr 25 16:57:32 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 16, len 34) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 17: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 17: c0 01 80 00 00 6e Apr 25 16:57:32 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 17, len 34) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 18: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 18: c0 01 80 00 00 86 Apr 25 16:57:32 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 18, len 34) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 19: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 19: c0 01 80 00 00 72 Apr 25 16:57:32 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 19, len 34) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 20: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 20: c0 01 80 00 00 04 Apr 25 16:57:32 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 20, len 34) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 21: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 21: c0 01 80 00 00 04 Apr 25 16:57:32 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 21, len 34) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 22: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 22: c0 01 80 00 00 04 Apr 25 16:57:32 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 22, len 34) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 23: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 23: c0 01 80 00 00 04 Apr 25 16:57:32 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 23, len 34) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 24: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 24: c0 01 80 00 00 04 Apr 25 16:57:32 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 24, len 34) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 25: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 25: c0 01 80 00 00 04 Apr 25 16:57:32 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 25, len 34) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Send complete in phase T30_PHASE_B_TX, state 15 Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Tx: DIS with final frame tag Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Tx: ff 13 80 05 ee fa c4 80 8d 80 80 80 18 Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 26: data v21/hdlc-fcs-OK + 0 byte(s) Apr 25 16:57:32 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 26: c0 01 20 Apr 25 16:57:32 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 26, len 31) Apr 25 16:57:33 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 27: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:33 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 27: c0 01 80 00 00 ff Apr 25 16:57:33 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 27, len 34) Apr 25 16:57:33 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 28: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:33 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 28: c0 01 80 00 00 c8 Apr 25 16:57:33 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 28, len 34) Apr 25 16:57:33 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 29: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:33 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 29: c0 01 80 00 00 01 Apr 25 16:57:33 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 29, len 34) Apr 25 16:57:33 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 30: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:33 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 30: c0 01 80 00 00 a0 Apr 25 16:57:33 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 30, len 34) Apr 25 16:57:33 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 31: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:33 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 31: c0 01 80 00 00 77 Apr 25 16:57:33 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 31, len 34) Apr 25 16:57:33 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 32: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:33 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 32: c0 01 80 00 00 5f Apr 25 16:57:33 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 32, len 34) Apr 25 16:57:33 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 33: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:33 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 33: c0 01 80 00 00 23 Apr 25 16:57:33 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 33, len 34) Apr 25 16:57:33 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 34: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:33 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 34: c0 01 80 00 00 01 Apr 25 16:57:33 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 34, len 34) Apr 25 16:57:33 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 35: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:33 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 35: c0 01 80 00 00 b1 Apr 25 16:57:33 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 35, len 34) Apr 25 16:57:33 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 36: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:33 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 36: c0 01 80 00 00 01 Apr 25 16:57:33 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 36, len 34) Apr 25 16:57:33 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 37: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:33 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 37: c0 01 80 00 00 01 Apr 25 16:57:33 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 37, len 34) Apr 25 16:57:33 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 38: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:33 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 38: c0 01 80 00 00 01 Apr 25 16:57:33 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 38, len 34) Apr 25 16:57:33 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 39: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:33 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 39: c0 01 80 00 00 18 Apr 25 16:57:33 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 39, len 34) Apr 25 16:57:33 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Send complete in phase T30_PHASE_B_TX, state 15 Apr 25 16:57:33 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 40: data v21/hdlc-fcs-OK-sig-end + 0 byte(s) Apr 25 16:57:33 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 40: c0 01 40 Apr 25 16:57:33 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 40, len 31) Apr 25 16:57:33 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 41: indicator no-signal Apr 25 16:57:33 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 41, len 29) Apr 25 16:57:33 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Send complete in phase T30_PHASE_B_TX, state 15 Apr 25 16:57:33 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Changing from phase T30_PHASE_B_TX to T30_PHASE_B_RX Apr 25 16:57:33 DEBUG[2983607200] app_rxfax.c: FLOW T.38T Set rx type 4 Apr 25 16:57:33 DEBUG[2983607200] app_rxfax.c: FLOW T.38T Set tx type 0 Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 T4 timeout in phase T30_PHASE_B_RX, state 15 Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Changing from phase T30_PHASE_B_RX to T30_PHASE_B_TX Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.38T Set rx type 0 Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.38T Set tx type 4 Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 DIS: Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... ...1= Store and forward Internet fax (T.37): Set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... .1..= Real-time Internet fax (T.38): Set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... 0...= 3G mobile network: Not set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 ..0. ....= V.8 capabilities: Not set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .0.. ....= Preferred octets: 256 octets Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... ...0= Ready to transmit a fax document (polling): Not set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... ..1.= Can receive fax: Set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 ..10 11..= Supported data signalling rates: V.27 ter, V.29, and V.17 Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .1.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 1... ....= 2-D coding: Set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... ..10= Recording width: 215 mm +- 1-0x1.38ef8b7e86f08p-226nd 255 mm +- 1 0x0.00005b7e0d57fp-1022nd 303 mm +- 1% Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... 10..= Recording length: Unlimited Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .111 ....= Receiver's minimum scan line time: 0 ms at 3.85 l/mm: T7.7 = T3.85 Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 1... ....= Extension indicator: Set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... ..0.= Compressed/uncompressed mode: Compressed Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... .1..= Error correction mode (ECM): ECM Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .1.. ....= T.6 coding: Set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 1... ....= Extension indicator: Set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... ...0= "Field not valid" supported: Not set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... ..0.= Multiple selective polling: Not set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... .0..= Polled subaddress: Not set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... 0...= T.43 coding: Not set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 ...0 ....= Plane interleave: Not set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 ..0. ....= Voice coding with 32kbit/s ADPCM (Rec. G.726): Not set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .0.. ....= Reserved for the use of extended voice coding set: Not set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 1... ....= Extension indicator: Set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... ...1= R8x15.4lines/mm: Set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... ..0.= 300x300pels/25.4mm: Not set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... .1..= R16x15.4lines/mm and/or 400x400pels/25.4 mm: Set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... 1...= Inch-based resolution preferred: Set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 ...0 ....= Metric-based resolution preferred: Not set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 ..0. ....= Minimum scan line time for higher resolutions: T15.4 = T7.7 Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .0.. ....= Selective polling: Not set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 1... ....= Extension indicator: Set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... ...0= Subaddressing: Not set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... ..0.= Password: Not set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... .0..= Ready to transmit a data file (polling): Not set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 ...0 ....= Binary file transfer (BFT): Not set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 ..0. ....= Document transfer mode (DTM): Not set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .0.. ....= Electronic data interchange (EDI): Not set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 1... ....= Extension indicator: Set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... ...0= Basic transfer mode (BTM): Not set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... .0..= Ready to transfer a character or mixed mode document (polling): Not set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... 0...= Character mode: Not set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 ..0. ....= Mixed mode (Annex E/T.4): Not set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 1... ....= Extension indicator: Set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... ...0= Processable mode 26 (Rec. T.505): Not set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... ..0.= Digital network capability: Not set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... .0..= Duplex capability: Half only Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... 0...= JPEG coding: Not set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 ...0 ....= Full colour mode: Not set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .0.. ....= 12bits/pel component: Not set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 1... ....= Extension indicator: Set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... ...0= No subsampling (1:1:1): Not set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... ..0.= Custom illuminant: Not set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... .0..= Custom gamut range: Not set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... 1...= North American Letter (215.9mm x 279.4mm): Set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 ...1 ....= North American Legal (215.9mm x 355.6mm): Set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 ..0. ....= Single-progression sequential coding (Rec. T.85) basic: Not set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .0.. ....= Single-progression sequential coding (Rec. T.85) optional L0: Not set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 0... ....= Extension indicator: Not set Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Sending ident 'Navynet.it FAX' Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Tx: CSI without final frame tag Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Tx: ff 03 40 58 41 46 20 74 69 2e 74 65 6e 79 76 61 4e 20 20 20 20 20 20 Apr 25 16:57:36 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 42: indicator v21-preamble Apr 25 16:57:36 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 42, len 29) Apr 25 16:57:37 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 43: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:37 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 43: c0 01 80 00 00 ff Apr 25 16:57:37 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 43, len 34) Apr 25 16:57:37 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 44: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:37 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 44: c0 01 80 00 00 c0 Apr 25 16:57:37 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 44, len 34) Apr 25 16:57:37 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 45: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:37 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 45: c0 01 80 00 00 02 Apr 25 16:57:37 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 45, len 34) Apr 25 16:57:37 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 46: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:37 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 46: c0 01 80 00 00 1a Apr 25 16:57:37 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 46, len 34) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 47: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 47: c0 01 80 00 00 82 Apr 25 16:57:38 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 47, len 34) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 48: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 48: c0 01 80 00 00 62 Apr 25 16:57:38 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 48, len 34) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 49: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 49: c0 01 80 00 00 04 Apr 25 16:57:38 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 49, len 34) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 50: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 50: c0 01 80 00 00 2e Apr 25 16:57:38 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 50, len 34) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 51: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 51: c0 01 80 00 00 96 Apr 25 16:57:38 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 51, len 34) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 52: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 52: c0 01 80 00 00 74 Apr 25 16:57:38 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 52, len 34) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 53: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 53: c0 01 80 00 00 2e Apr 25 16:57:38 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 53, len 34) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 54: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 54: c0 01 80 00 00 a6 Apr 25 16:57:38 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 54, len 34) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 55: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 55: c0 01 80 00 00 76 Apr 25 16:57:38 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 55, len 34) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 56: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 56: c0 01 80 00 00 9e Apr 25 16:57:38 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 56, len 34) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 57: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 57: c0 01 80 00 00 6e Apr 25 16:57:38 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 57, len 34) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 58: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 58: c0 01 80 00 00 86 Apr 25 16:57:38 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 58, len 34) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 59: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 59: c0 01 80 00 00 72 Apr 25 16:57:38 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 59, len 34) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 60: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 60: c0 01 80 00 00 04 Apr 25 16:57:38 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 60, len 34) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 61: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 61: c0 01 80 00 00 04 Apr 25 16:57:38 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 61, len 34) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 62: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 62: c0 01 80 00 00 04 Apr 25 16:57:38 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 62, len 34) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 63: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 63: c0 01 80 00 00 04 Apr 25 16:57:38 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 63, len 34) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 64: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 64: c0 01 80 00 00 04 Apr 25 16:57:38 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 64, len 34) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 65: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 65: c0 01 80 00 00 04 Apr 25 16:57:38 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 65, len 34) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Send complete in phase T30_PHASE_B_TX, state 15 Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Tx: DIS with final frame tag Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Tx: ff 13 80 05 ee fa c4 80 8d 80 80 80 18 Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 66: data v21/hdlc-fcs-OK + 0 byte(s) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 66: c0 01 20 Apr 25 16:57:38 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 66, len 31) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 67: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 67: c0 01 80 00 00 ff Apr 25 16:57:38 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 67, len 34) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 68: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 68: c0 01 80 00 00 c8 Apr 25 16:57:38 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 68, len 34) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 69: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 69: c0 01 80 00 00 01 Apr 25 16:57:38 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 69, len 34) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 70: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 70: c0 01 80 00 00 a0 Apr 25 16:57:38 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 70, len 34) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 71: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 71: c0 01 80 00 00 77 Apr 25 16:57:38 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 71, len 34) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 72: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 72: c0 01 80 00 00 5f Apr 25 16:57:38 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 72, len 34) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 73: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 73: c0 01 80 00 00 23 Apr 25 16:57:38 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 73, len 34) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 74: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 74: c0 01 80 00 00 01 Apr 25 16:57:38 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 74, len 34) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 75: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 75: c0 01 80 00 00 b1 Apr 25 16:57:38 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 75, len 34) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 76: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 76: c0 01 80 00 00 01 Apr 25 16:57:38 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 76, len 34) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 77: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 77: c0 01 80 00 00 01 Apr 25 16:57:38 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 77, len 34) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 78: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 78: c0 01 80 00 00 01 Apr 25 16:57:38 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 78, len 34) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 79: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 79: c0 01 80 00 00 18 Apr 25 16:57:38 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 79, len 34) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Send complete in phase T30_PHASE_B_TX, state 15 Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 80: data v21/hdlc-fcs-OK-sig-end + 0 byte(s) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 80: c0 01 40 Apr 25 16:57:38 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 80, len 31) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 81: indicator no-signal Apr 25 16:57:38 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 81, len 29) Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Send complete in phase T30_PHASE_B_TX, state 15 Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Changing from phase T30_PHASE_B_TX to T30_PHASE_B_RX Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38T Set rx type 4 Apr 25 16:57:38 DEBUG[2983607200] app_rxfax.c: FLOW T.38T Set tx type 0 Apr 25 16:57:39 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 10) Apr 25 16:57:39 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 1: 06 Apr 25 16:57:39 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 1: indicator v21-preamble Apr 25 16:57:39 DEBUG[2983607200] app_rxfax.c: FLOW T.30 HDLC carrier up in state 15 Apr 25 16:57:39 DEBUG[2983607200] app_rxfax.c: FLOW T.30 HDLC framing OK in state 15 Apr 25 16:57:39 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 10) Apr 25 16:57:39 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 1: 06 Apr 25 16:57:39 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 1: Repeat packet number Apr 25 16:57:39 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 10) Apr 25 16:57:39 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 1: 06 Apr 25 16:57:39 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 1: Repeat packet number Apr 25 16:57:40 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 15) Apr 25 16:57:40 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 65533: 00 Apr 25 16:57:40 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 65533: Late packet - expected 2 Apr 25 16:57:40 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 65534: 00 Apr 25 16:57:40 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 65534: Late packet - expected 2 Apr 25 16:57:40 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 65535: 00 Apr 25 16:57:40 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 65535: Late packet - expected 2 Apr 25 16:57:40 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 2: c0 01 80 00 00 ff Apr 25 16:57:40 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 2: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:40 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 20) Apr 25 16:57:40 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 3: c0 01 80 00 00 c0 Apr 25 16:57:40 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 3: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:40 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 20) Apr 25 16:57:40 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 4: c0 01 80 00 00 c2 Apr 25 16:57:40 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 4: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:41 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 20) Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 5: c0 01 80 00 00 ac Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 5: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:41 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 20) Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 6: c0 01 80 00 00 4c Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 6: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:41 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 20) Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 7: c0 01 80 00 00 4c Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 7: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:41 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 20) Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 8: c0 01 80 00 00 6c Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 8: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:41 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 20) Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 9: c0 01 80 00 00 1c Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 9: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:41 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 20) Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 10: c0 01 80 00 00 6c Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 10: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:41 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 20) Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 11: c0 01 80 00 00 6c Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 11: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:41 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 20) Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 12: c0 01 80 00 00 6c Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 12: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:41 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 20) Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 13: c0 01 80 00 00 6c Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 13: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:41 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 20) Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 14: c0 01 80 00 00 1c Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 14: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:41 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 20) Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 15: c0 01 80 00 00 8c Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 15: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:41 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 20) Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 16: c0 01 80 00 00 04 Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 16: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:41 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 20) Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 17: c0 01 80 00 00 04 Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 17: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:41 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 20) Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 18: c0 01 80 00 00 04 Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 18: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:41 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 20) Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 19: c0 01 80 00 00 04 Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 19: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:41 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 20) Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 20: c0 01 80 00 00 04 Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 20: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:41 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 20) Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 21: c0 01 80 00 00 04 Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 21: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:41 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 20) Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 22: c0 01 80 00 00 04 Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 22: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:41 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 20) Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 23: c0 01 80 00 00 04 Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 23: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:41 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 20) Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 24: c0 01 80 00 00 04 Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 24: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:41 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 17) Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 25: c0 01 20 Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 25: data v21/hdlc-fcs-OK + 0 byte(s) Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38T Type TSI - CRC OK (clean) Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Rx: TSI without final frame tag Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Rx: ff 03 43 35 32 32 36 38 36 36 36 36 38 31 20 20 20 20 20 20 20 20 20 Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Remote fax gave TSI as: "18666686225" Apr 25 16:57:41 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 20) Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 26: c0 01 80 00 00 ff Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 26: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:41 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 20) Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 27: c0 01 80 00 00 c8 Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 27: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:41 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 20) Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 28: c0 01 80 00 00 c1 Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 28: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:41 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 20) Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 29: c0 01 80 00 00 00 Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 29: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:41 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 20) Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 30: c0 01 80 00 00 60 Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 30: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:41 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 20) Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 31: c0 01 80 00 00 15 Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 31: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:41 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 20) Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 32: c0 01 80 00 00 01 Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 32: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:41 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 20) Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 33: c0 01 80 00 00 01 Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 33: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:41 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 20) Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 34: c0 01 80 00 00 00 Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 34: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:41 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 17) Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 35: c0 01 40 Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 35: data v21/hdlc-fcs-OK-sig-end + 0 byte(s) Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38T Type DCS - CRC OK, sig end (clean) Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Rx: DCS with final frame tag Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Rx: ff 13 83 00 06 a8 80 80 00 Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 In state 15 Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 DCS: Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... ...0= Store and forward Internet fax (T.37): Not set Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... .0..= Real-time Internet fax (T.38): Not set Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... 0...= 3G mobile network: Not set Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... ..1.= Can receive fax: Set Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 ..00 01..= Selected data signalling rate: V.29, 9600bps Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .0.. ....= R8x7.7lines/mm and/or 200x200pels/25.4mm: Not set Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 0... ....= 2-D coding: Not set Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... ..00= Recording width: 215 mm +- 1% Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... 10..= Recording length: Unlimited Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .010 ....= Minimum scan line time: 10 ms Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 1... ....= Extension indicator: Set Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... ..0.= Compressed/uncompressed mode: Compressed Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... .0..= Error correction mode (ECM): Non-ECM Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... 0...= Frame size: 256 octets Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .0.. ....= T.6 coding: Not set Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 1... ....= Extension indicator: Set Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... ...0= "Field not valid" supported: Not set Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... 0...= T.43 coding: Not set Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 ...0 ....= Plane interleave: Not set Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 ..0. ....= Voice coding with 32kbit/s ADPCM (Rec. G.726): Not set Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .0.. ....= Reserved for the use of extended voice coding set: Not set Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 1... ....= Extension indicator: Set Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... ...0= R8x15.4lines/mm: Not set Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... ..0.= 300x300pels/25.4mm: Not set Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... .0..= R16x15.4lines/mm and/or 400x400pels/25.4 mm: Not set Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 .... 0...= Resolution type selection: Metric Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 0... ....= Extension indicator: Not set Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Selected compression 1 Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Get document at 9600bps, modem 8 Apr 25 16:57:41 WARNING[2983607200] app_rxfax.c: WARNING T.30 Cannot open target TIFF file '(/opt/tmp/fax.tif' Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Changing from state 15 to 3 Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Tx: DCN with final frame tag Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Tx: ff 13 fa Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 HDLC carrier down in state 3 Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Changing from phase T30_PHASE_B_RX to T30_PHASE_D_TX Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38T Set rx type 0 Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38T Set tx type 4 Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 82: indicator v21-preamble Apr 25 16:57:41 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 82, len 29) Apr 25 16:57:41 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 15) Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 36: 00 Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 36: indicator no-signal Apr 25 16:57:41 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 15) Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 36: 00 Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 36: Repeat packet number Apr 25 16:57:41 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 15) Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 36: 00 Apr 25 16:57:41 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 36: Repeat packet number Apr 25 16:57:42 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 15) Apr 25 16:57:42 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 37: 0e Apr 25 16:57:42 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 37: indicator v29-9600-training Apr 25 16:57:42 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 15) Apr 25 16:57:42 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 37: 0e Apr 25 16:57:42 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 37: Repeat packet number Apr 25 16:57:42 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 15) Apr 25 16:57:42 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 37: 0e Apr 25 16:57:42 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 37: Repeat packet number Apr 25 16:57:42 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 64) Apr 25 16:57:42 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 38: c8 01 e0 00 2f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 Apr 25 16:57:42 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 38: data v29-9600/t4-non-ecm-data + 48 byte(s) Apr 25 16:57:42 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Non-ECM carrier trained in state 3 Apr 25 16:57:42 VERBOSE[2983607200] logger.c: Got UDPTL packet from 10.10.7.37:5008 (len 114) Apr 25 16:57:42 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 39: c8 01 e0 00 2f 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 Apr 25 16:57:42 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Rx 39: data v29-9600/t4-non-ecm-data + 48 byte(s) Apr 25 16:57:42 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 83: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:42 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 83: c0 01 80 00 00 ff Apr 25 16:57:42 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 83, len 34) Apr 25 16:57:42 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 84: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:42 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 84: c0 01 80 00 00 c8 Apr 25 16:57:42 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 84, len 34) Apr 25 16:57:42 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 85: data v21/hdlc-data + 1 byte(s) Apr 25 16:57:42 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 85: c0 01 80 00 00 5f Apr 25 16:57:42 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 85, len 34) Apr 25 16:57:42 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Send complete in phase T30_PHASE_D_TX, state 3 Apr 25 16:57:42 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 86: data v21/hdlc-fcs-OK-sig-end + 0 byte(s) Apr 25 16:57:42 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 86: c0 01 40 Apr 25 16:57:42 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 86, len 31) Apr 25 16:57:42 DEBUG[2983607200] app_rxfax.c: FLOW T.38 Tx 87: indicator no-signal Apr 25 16:57:42 VERBOSE[2983607200] logger.c: Sent UDPTL packet to 10.10.7.37:5008 (seq 87, len 29) Apr 25 16:57:42 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Send complete in phase T30_PHASE_D_TX, state 3 Apr 25 16:57:42 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Disconnecting Apr 25 16:57:42 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Changing from phase T30_PHASE_D_TX to T30_PHASE_E Apr 25 16:57:42 DEBUG[2983607200] app_rxfax.c: FLOW T.38T Set rx type 0 Apr 25 16:57:42 DEBUG[2983607200] app_rxfax.c: FLOW T.38T Set tx type 1 Apr 25 16:57:42 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Changing from state 3 to 2 Apr 25 16:57:44 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Send complete in phase T30_PHASE_E, state 2 Apr 25 16:57:44 DEBUG[2983607200] app_rxfax.c: ============================================================================== Apr 25 16:57:44 DEBUG[2983607200] app_rxfax.c: Fax receive not successful - result (14) TIFF/F file cannot be opened. Apr 25 16:57:44 DEBUG[2983607200] app_rxfax.c: ============================================================================== Apr 25 16:57:44 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Changing from state 2 to 30 Apr 25 16:57:44 DEBUG[2983607200] app_rxfax.c: FLOW T.30 Changing from phase T30_PHASE_E to T30_PHASE_CALL_FINISHED Apr 25 16:57:44 DEBUG[2983607200] app_rxfax.c: FLOW T.38T Set rx type 13 Apr 25 16:57:44 DEBUG[2983607200] app_rxfax.c: FLOW T.38T Set tx type 13 Apr 25 16:57:44 DEBUG[2983607200] app_rxfax.c: FLOW T.38T FAX exchange complete Apr 25 16:57:44 DEBUG[2983607200] channel.c: Set channel SIP/400-66a0 to read format ulaw Apr 25 16:57:44 DEBUG[2983607200] channel.c: Set channel SIP/400-66a0 to write format ulaw Apr 25 16:57:44 DEBUG[2983607200] pbx.c: Launching 'NoOp' Apr 25 16:57:44 VERBOSE[2983607200] logger.c: -- Executing NoOp("SIP/400-66a0", "RX: REMOTESTATIONID is 18666686225") in new stack Apr 25 16:57:44 DEBUG[2983607200] pbx.c: Launching 'NoOp' Apr 25 16:57:44 VERBOSE[2983607200] logger.c: -- Executing NoOp("SIP/400-66a0", "RX: PHASEESTATUS is 14") in new stack Apr 25 16:57:44 DEBUG[2983607200] pbx.c: Launching 'Hangup' Apr 25 16:57:44 VERBOSE[2983607200] logger.c: -- Executing Hangup("SIP/400-66a0", "") in new stack Apr 25 16:57:44 DEBUG[2983607200] pbx.c: Spawn extension (sipfax,fax,5) exited non-zero on 'SIP/400-66a0' Apr 25 16:57:44 VERBOSE[2983607200] logger.c: == Spawn extension (sipfax, fax, 5) exited non-zero on 'SIP/400-66a0' Apr 25 16:57:44 DEBUG[2983607200] cdr_sqlite3.c: CDR SQLITE3 SQL [INSERT INTO cdr (clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata, start,answer,end,duration,billsec,disposition,amaflags, accountcode) VALUES ('"ATA" <400>', '400', 'fax', 'sipfax', 'SIP/400-66a0', '', 'Hangup', '', '2007-04-25 16:57:25', '2007-04-25 16:57:25', '2007-04-25 16:57:44', 19, 19, 4, 3, '')] Apr 25 16:57:44 DEBUG[2983607200] pbx.c: Function result is '"ATA" <400>' Apr 25 16:57:44 DEBUG[2983607200] pbx.c: Function result is '400' Apr 25 16:57:44 DEBUG[2983607200] pbx.c: Function result is 'fax' Apr 25 16:57:44 DEBUG[2983607200] pbx.c: Function result is 'sipfax' Apr 25 16:57:44 DEBUG[2983607200] pbx.c: Function result is 'SIP/400-66a0' Apr 25 16:57:44 DEBUG[2983607200] pbx.c: Function result is '(null)' Apr 25 16:57:44 DEBUG[2983607200] pbx.c: Function result is 'Hangup' Apr 25 16:57:44 DEBUG[2983607200] pbx.c: Function result is '(null)' Apr 25 16:57:44 DEBUG[2983607200] pbx.c: Function result is '2007-04-25 16:57:25' Apr 25 16:57:44 DEBUG[2983607200] pbx.c: Function result is '2007-04-25 16:57:25' Apr 25 16:57:44 DEBUG[2983607200] pbx.c: Function result is '2007-04-25 16:57:44' Apr 25 16:57:44 DEBUG[2983607200] pbx.c: Function result is '19' Apr 25 16:57:44 DEBUG[2983607200] pbx.c: Function result is '19' Apr 25 16:57:44 DEBUG[2983607200] pbx.c: Function result is 'ANSWERED' Apr 25 16:57:44 DEBUG[2983607200] pbx.c: Function result is 'DOCUMENTATION' Apr 25 16:57:44 DEBUG[2983607200] pbx.c: Function result is '(null)' Apr 25 16:57:44 DEBUG[2983607200] pbx.c: Function result is '1177534645.0' Apr 25 16:57:44 DEBUG[2983607200] pbx.c: Function result is '(null)' Apr 25 16:57:44 DEBUG[2983607200] channel.c: Hanging up channel 'SIP/400-66a0' Apr 25 16:57:44 DEBUG[2983607200] chan_sip.c: Hangup call SIP/400-66a0, SIP callid f66398437721a5ce@10.10.7.37) Apr 25 16:57:44 DEBUG[2983607200] chan_sip.c: update_call_counter(400) - decrement call limit counter Apr 25 16:57:44 DEBUG[2983607200] chan_sip.c: Updating call counter for outgoing call Apr 25 16:57:44 VERBOSE[2983607200] logger.c: Scheduling destruction of call 'f66398437721a5ce@10.10.7.37' in 32000 ms Apr 25 16:57:44 VERBOSE[2983607200] logger.c: set_destination: Parsing for address/port to send to Apr 25 16:57:44 VERBOSE[2983607200] logger.c: set_destination: set destination to 10.10.7.37, port 5060 Apr 25 16:57:44 VERBOSE[2983607200] logger.c: Reliably Transmitting (NAT) to 10.10.7.37:5060: BYE sip:400@10.10.7.37 SIP/2.0 Via: SIP/2.0/UDP 10.10.250.62:5060;branch=z9hG4bK1eb89a48 From: ;tag=as73a4778b To: ;tag=40e2b4adca7ff28f Contact: Call-ID: f66398437721a5ce@10.10.7.37 CSeq: 103 BYE User-Agent: CallWeaver Max-Forwards: 70 Content-Length: 0 --- Apr 25 16:57:44 DEBUG[2983607200] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #14 Apr 25 16:57:44 DEBUG[2983607200] channel.c: Generator : deactivate after channel unlock (hangup function) Apr 25 16:57:44 DEBUG[2983607200] generator.c: Trying to deactivate generator in SIP/400-66a0 Apr 25 16:57:44 VERBOSE[2988723104] logger.c: <-- SIP read from 10.10.7.37:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.10.250.62:5060;branch=z9hG4bK1eb89a48 From: ;tag=as73a4778b To: ;tag=40e2b4adca7ff28f Call-ID: f66398437721a5ce@10.10.7.37 CSeq: 103 BYE User-Agent: Grandstream HT386 1.0.3.64 FXS1 Contact: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Supported: replaces Content-Length: 0 Apr 25 16:57:44 DEBUG[2988723104] chan_sip.c: Header 0: SIP/2.0 200 OK (14) Apr 25 16:57:44 DEBUG[2988723104] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.10.250.62:5060;branch=z9hG4bK1eb89a48 (57) Apr 25 16:57:44 DEBUG[2988723104] chan_sip.c: Header 2: From: ;tag=as73a4778b (43) Apr 25 16:57:44 DEBUG[2988723104] chan_sip.c: Header 3: To: ;tag=40e2b4adca7ff28f (47) Apr 25 16:57:44 DEBUG[2988723104] chan_sip.c: Header 4: Call-ID: f66398437721a5ce@10.10.7.37 (36) Apr 25 16:57:44 DEBUG[2988723104] chan_sip.c: Header 5: CSeq: 103 BYE (13) Apr 25 16:57:44 DEBUG[2988723104] chan_sip.c: Header 6: User-Agent: Grandstream HT386 1.0.3.64 FXS1 (43) Apr 25 16:57:44 DEBUG[2988723104] chan_sip.c: Header 7: Contact: (29) Apr 25 16:57:44 DEBUG[2988723104] chan_sip.c: Header 8: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE (64) Apr 25 16:57:44 DEBUG[2988723104] chan_sip.c: Header 9: Supported: replaces (19) Apr 25 16:57:44 DEBUG[2988723104] chan_sip.c: Header 10: Content-Length: 0 (17) Apr 25 16:57:44 DEBUG[2988723104] chan_sip.c: Header 11: (0) Apr 25 16:57:44 VERBOSE[2988723104] logger.c: --- (11 headers 0 lines) --- Apr 25 16:57:44 DEBUG[2988723104] chan_sip.c: = Found Their Call ID: f66398437721a5ce@10.10.7.37 Their Tag 40e2b4adca7ff28f Our tag: as73a4778b Apr 25 16:57:44 DEBUG[2988723104] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #14 Apr 25 16:57:44 DEBUG[2988723104] chan_sip.c: Stopping retransmission on 'f66398437721a5ce@10.10.7.37' of Request 103: Match Found Apr 25 16:57:44 VERBOSE[2988723104] logger.c: Destroying call 'f66398437721a5ce@10.10.7.37' Apr 25 16:57:44 DEBUG[2983607200] generator.c: Generator on SIP/400-66a0 stopped after 0 iterations Apr 25 16:57:44 DEBUG[3079719840] chan_sip.c: Checking device state for peer 400 Apr 25 16:57:44 DEBUG[3079719840] devicestate.c: Changing state for SIP/400 - state 1 (Not in use) Apr 25 16:57:44 DEBUG[2983607200] app_queue.c: Device 'SIP/400' changed to state '1' (Not in use) Apr 25 16:57:54 VERBOSE[2983873440] logger.c: -- Remote UNIX connection disconnected Apr 25 16:58:09 DEBUG[2988723104] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) Apr 25 16:58:09 DEBUG[2988723104] chan_sip.c: Header 0: OPTIONS sip:400@10.10.7.37 SIP/2.0 (34) Apr 25 16:58:09 DEBUG[2988723104] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.10.250.62:5060;branch=z9hG4bK3e2c8960 (57) Apr 25 16:58:09 DEBUG[2988723104] chan_sip.c: Header 2: From: "callweaver" ;tag=as315d23c2 (63) Apr 25 16:58:09 DEBUG[2988723104] chan_sip.c: Header 3: To: (24) Apr 25 16:58:09 DEBUG[2988723104] chan_sip.c: Header 4: Contact: (38) Apr 25 16:58:09 DEBUG[2988723104] chan_sip.c: Header 5: Call-ID: 478c715a657d126b40de5d21546ed0ae@10.10.250.62 (54) Apr 25 16:58:09 DEBUG[2988723104] chan_sip.c: Header 6: CSeq: 102 OPTIONS (17) Apr 25 16:58:09 DEBUG[2988723104] chan_sip.c: Header 7: User-Agent: CallWeaver (22) Apr 25 16:58:09 DEBUG[2988723104] chan_sip.c: Header 8: Max-Forwards: 70 (16) Apr 25 16:58:09 DEBUG[2988723104] chan_sip.c: Header 9: Date: Wed, 25 Apr 2007 20:58:09 GMT (35) Apr 25 16:58:09 DEBUG[2988723104] chan_sip.c: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) Apr 25 16:58:09 DEBUG[2988723104] chan_sip.c: Header 11: Content-Length: 0 (17) Apr 25 16:58:09 DEBUG[2988723104] chan_sip.c: Header 12: (0) Apr 25 16:58:09 VERBOSE[2988723104] logger.c: 12 headers, 0 lines Apr 25 16:58:09 VERBOSE[2988723104] logger.c: Reliably Transmitting (NAT) to 10.10.7.37:5060: OPTIONS sip:400@10.10.7.37 SIP/2.0 Via: SIP/2.0/UDP 10.10.250.62:5060;branch=z9hG4bK3e2c8960 From: "callweaver" ;tag=as315d23c2 To: Contact: Call-ID: 478c715a657d126b40de5d21546ed0ae@10.10.250.62 CSeq: 102 OPTIONS User-Agent: CallWeaver Max-Forwards: 70 Date: Wed, 25 Apr 2007 20:58:09 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Length: 0 --- Apr 25 16:58:09 DEBUG[2988723104] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #15 Apr 25 16:58:09 VERBOSE[2988723104] logger.c: <-- SIP read from 10.10.7.37:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.10.250.62:5060;branch=z9hG4bK3e2c8960 From: "callweaver" ;tag=as315d23c2 To: ;tag=2249234db585fb57 Call-ID: 478c715a657d126b40de5d21546ed0ae@10.10.250.62 CSeq: 102 OPTIONS User-Agent: Grandstream HT386 1.0.3.64 FXS1 Contact: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Supported: replaces Content-Length: 0 Apr 25 16:58:09 DEBUG[2988723104] chan_sip.c: Header 0: SIP/2.0 200 OK (14) Apr 25 16:58:09 DEBUG[2988723104] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.10.250.62:5060;branch=z9hG4bK3e2c8960 (57) Apr 25 16:58:09 DEBUG[2988723104] chan_sip.c: Header 2: From: "callweaver" ;tag=as315d23c2 (63) Apr 25 16:58:09 DEBUG[2988723104] chan_sip.c: Header 3: To: ;tag=2249234db585fb57 (45) Apr 25 16:58:09 DEBUG[2988723104] chan_sip.c: Header 4: Call-ID: 478c715a657d126b40de5d21546ed0ae@10.10.250.62 (54) Apr 25 16:58:09 DEBUG[2988723104] chan_sip.c: Header 5: CSeq: 102 OPTIONS (17) Apr 25 16:58:09 DEBUG[2988723104] chan_sip.c: Header 6: User-Agent: Grandstream HT386 1.0.3.64 FXS1 (43) Apr 25 16:58:09 DEBUG[2988723104] chan_sip.c: Header 7: Contact: (29) Apr 25 16:58:09 DEBUG[2988723104] chan_sip.c: Header 8: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE (64) Apr 25 16:58:09 DEBUG[2988723104] chan_sip.c: Header 9: Supported: replaces (19) Apr 25 16:58:09 DEBUG[2988723104] chan_sip.c: Header 10: Content-Length: 0 (17) Apr 25 16:58:09 DEBUG[2988723104] chan_sip.c: Header 11: (0) Apr 25 16:58:09 VERBOSE[2988723104] logger.c: --- (11 headers 0 lines) --- Apr 25 16:58:09 DEBUG[2988723104] chan_sip.c: = Found Their Call ID: 478c715a657d126b40de5d21546ed0ae@10.10.250.62 Their Tag Our tag: as315d23c2 Apr 25 16:58:09 DEBUG[2988723104] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #15 Apr 25 16:58:09 DEBUG[2988723104] chan_sip.c: Stopping retransmission on '478c715a657d126b40de5d21546ed0ae@10.10.250.62' of Request 102: Match Found Apr 25 16:58:09 VERBOSE[2988723104] logger.c: Destroying call '478c715a657d126b40de5d21546ed0ae@10.10.250.62' Apr 25 16:59:09 DEBUG[2988723104] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) Apr 25 16:59:09 DEBUG[2988723104] chan_sip.c: Header 0: OPTIONS sip:400@10.10.7.37 SIP/2.0 (34) Apr 25 16:59:09 DEBUG[2988723104] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.10.250.62:5060;branch=z9hG4bK4f349c26 (57) Apr 25 16:59:09 DEBUG[2988723104] chan_sip.c: Header 2: From: "callweaver" ;tag=as5ac7325e (63) Apr 25 16:59:09 DEBUG[2988723104] chan_sip.c: Header 3: To: (24) Apr 25 16:59:09 DEBUG[2988723104] chan_sip.c: Header 4: Contact: (38) Apr 25 16:59:09 DEBUG[2988723104] chan_sip.c: Header 5: Call-ID: 5a0da3e651ff752e4c54e72f0d85b27d@10.10.250.62 (54) Apr 25 16:59:09 DEBUG[2988723104] chan_sip.c: Header 6: CSeq: 102 OPTIONS (17) Apr 25 16:59:09 DEBUG[2988723104] chan_sip.c: Header 7: User-Agent: CallWeaver (22) Apr 25 16:59:09 DEBUG[2988723104] chan_sip.c: Header 8: Max-Forwards: 70 (16) Apr 25 16:59:09 DEBUG[2988723104] chan_sip.c: Header 9: Date: Wed, 25 Apr 2007 20:59:09 GMT (35) Apr 25 16:59:09 DEBUG[2988723104] chan_sip.c: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) Apr 25 16:59:09 DEBUG[2988723104] chan_sip.c: Header 11: Content-Length: 0 (17) Apr 25 16:59:09 DEBUG[2988723104] chan_sip.c: Header 12: (0) Apr 25 16:59:09 VERBOSE[2988723104] logger.c: 12 headers, 0 lines Apr 25 16:59:09 VERBOSE[2988723104] logger.c: Reliably Transmitting (NAT) to 10.10.7.37:5060: OPTIONS sip:400@10.10.7.37 SIP/2.0 Via: SIP/2.0/UDP 10.10.250.62:5060;branch=z9hG4bK4f349c26 From: "callweaver" ;tag=as5ac7325e To: Contact: Call-ID: 5a0da3e651ff752e4c54e72f0d85b27d@10.10.250.62 CSeq: 102 OPTIONS User-Agent: CallWeaver Max-Forwards: 70 Date: Wed, 25 Apr 2007 20:59:09 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Length: 0 --- Apr 25 16:59:09 DEBUG[2988723104] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #18 Apr 25 16:59:09 VERBOSE[2988723104] logger.c: <-- SIP read from 10.10.7.37:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.10.250.62:5060;branch=z9hG4bK4f349c26 From: "callweaver" ;tag=as5ac7325e To: ;tag=336a6a73710cfe32 Call-ID: 5a0da3e651ff752e4c54e72f0d85b27d@10.10.250.62 CSeq: 102 OPTIONS User-Agent: Grandstream HT386 1.0.3.64 FXS1 Contact: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Supported: replaces Content-Length: 0 Apr 25 16:59:09 DEBUG[2988723104] chan_sip.c: Header 0: SIP/2.0 200 OK (14) Apr 25 16:59:09 DEBUG[2988723104] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.10.250.62:5060;branch=z9hG4bK4f349c26 (57) Apr 25 16:59:09 DEBUG[2988723104] chan_sip.c: Header 2: From: "callweaver" ;tag=as5ac7325e (63) Apr 25 16:59:09 DEBUG[2988723104] chan_sip.c: Header 3: To: ;tag=336a6a73710cfe32 (45) Apr 25 16:59:09 DEBUG[2988723104] chan_sip.c: Header 4: Call-ID: 5a0da3e651ff752e4c54e72f0d85b27d@10.10.250.62 (54) Apr 25 16:59:09 DEBUG[2988723104] chan_sip.c: Header 5: CSeq: 102 OPTIONS (17) Apr 25 16:59:09 DEBUG[2988723104] chan_sip.c: Header 6: User-Agent: Grandstream HT386 1.0.3.64 FXS1 (43) Apr 25 16:59:09 DEBUG[2988723104] chan_sip.c: Header 7: Contact: (29) Apr 25 16:59:09 DEBUG[2988723104] chan_sip.c: Header 8: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE (64) Apr 25 16:59:09 DEBUG[2988723104] chan_sip.c: Header 9: Supported: replaces (19) Apr 25 16:59:09 DEBUG[2988723104] chan_sip.c: Header 10: Content-Length: 0 (17) Apr 25 16:59:09 DEBUG[2988723104] chan_sip.c: Header 11: (0) Apr 25 16:59:09 VERBOSE[2988723104] logger.c: --- (11 headers 0 lines) --- Apr 25 16:59:09 DEBUG[2988723104] chan_sip.c: = Found Their Call ID: 5a0da3e651ff752e4c54e72f0d85b27d@10.10.250.62 Their Tag Our tag: as5ac7325e Apr 25 16:59:09 DEBUG[2988723104] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #18 Apr 25 16:59:09 DEBUG[2988723104] chan_sip.c: Stopping retransmission on '5a0da3e651ff752e4c54e72f0d85b27d@10.10.250.62' of Request 102: Match Found Apr 25 16:59:09 VERBOSE[2988723104] logger.c: Destroying call '5a0da3e651ff752e4c54e72f0d85b27d@10.10.250.62' Apr 25 17:00:09 DEBUG[2988723104] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) Apr 25 17:00:09 DEBUG[2988723104] chan_sip.c: Header 0: OPTIONS sip:400@10.10.7.37 SIP/2.0 (34) Apr 25 17:00:09 DEBUG[2988723104] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.10.250.62:5060;branch=z9hG4bK43d99882 (57) Apr 25 17:00:09 DEBUG[2988723104] chan_sip.c: Header 2: From: "callweaver" ;tag=as392cd96c (63) Apr 25 17:00:09 DEBUG[2988723104] chan_sip.c: Header 3: To: (24) Apr 25 17:00:09 DEBUG[2988723104] chan_sip.c: Header 4: Contact: (38) Apr 25 17:00:09 DEBUG[2988723104] chan_sip.c: Header 5: Call-ID: 4f785bbb375a2e2016d0b326268ad1ec@10.10.250.62 (54) Apr 25 17:00:09 DEBUG[2988723104] chan_sip.c: Header 6: CSeq: 102 OPTIONS (17) Apr 25 17:00:09 DEBUG[2988723104] chan_sip.c: Header 7: User-Agent: CallWeaver (22) Apr 25 17:00:09 DEBUG[2988723104] chan_sip.c: Header 8: Max-Forwards: 70 (16) Apr 25 17:00:09 DEBUG[2988723104] chan_sip.c: Header 9: Date: Wed, 25 Apr 2007 21:00:09 GMT (35) Apr 25 17:00:09 DEBUG[2988723104] chan_sip.c: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) Apr 25 17:00:09 DEBUG[2988723104] chan_sip.c: Header 11: Content-Length: 0 (17) Apr 25 17:00:09 DEBUG[2988723104] chan_sip.c: Header 12: (0) Apr 25 17:00:09 VERBOSE[2988723104] logger.c: 12 headers, 0 lines Apr 25 17:00:09 VERBOSE[2988723104] logger.c: Reliably Transmitting (NAT) to 10.10.7.37:5060: OPTIONS sip:400@10.10.7.37 SIP/2.0 Via: SIP/2.0/UDP 10.10.250.62:5060;branch=z9hG4bK43d99882 From: "callweaver" ;tag=as392cd96c To: Contact: Call-ID: 4f785bbb375a2e2016d0b326268ad1ec@10.10.250.62 CSeq: 102 OPTIONS User-Agent: CallWeaver Max-Forwards: 70 Date: Wed, 25 Apr 2007 21:00:09 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Length: 0 --- Apr 25 17:00:09 DEBUG[2988723104] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #21 Apr 25 17:00:09 VERBOSE[2988723104] logger.c: <-- SIP read from 10.10.7.37:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.10.250.62:5060;branch=z9hG4bK43d99882 From: "callweaver" ;tag=as392cd96c To: ;tag=73ff2b668eb6ea61 Call-ID: 4f785bbb375a2e2016d0b326268ad1ec@10.10.250.62 CSeq: 102 OPTIONS User-Agent: Grandstream HT386 1.0.3.64 FXS1 Contact: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Supported: replaces Content-Length: 0 Apr 25 17:00:09 DEBUG[2988723104] chan_sip.c: Header 0: SIP/2.0 200 OK (14) Apr 25 17:00:09 DEBUG[2988723104] chan_sip.c: Header 1: Via: SIP/2.0/UDP 10.10.250.62:5060;branch=z9hG4bK43d99882 (57) Apr 25 17:00:09 DEBUG[2988723104] chan_sip.c: Header 2: From: "callweaver" ;tag=as392cd96c (63) Apr 25 17:00:09 DEBUG[2988723104] chan_sip.c: Header 3: To: ;tag=73ff2b668eb6ea61 (45) Apr 25 17:00:09 DEBUG[2988723104] chan_sip.c: Header 4: Call-ID: 4f785bbb375a2e2016d0b326268ad1ec@10.10.250.62 (54) Apr 25 17:00:09 DEBUG[2988723104] chan_sip.c: Header 5: CSeq: 102 OPTIONS (17) Apr 25 17:00:09 DEBUG[2988723104] chan_sip.c: Header 6: User-Agent: Grandstream HT386 1.0.3.64 FXS1 (43) Apr 25 17:00:09 DEBUG[2988723104] chan_sip.c: Header 7: Contact: (29) Apr 25 17:00:09 DEBUG[2988723104] chan_sip.c: Header 8: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE (64) Apr 25 17:00:09 DEBUG[2988723104] chan_sip.c: Header 9: Supported: replaces (19) Apr 25 17:00:09 DEBUG[2988723104] chan_sip.c: Header 10: Content-Length: 0 (17) Apr 25 17:00:09 DEBUG[2988723104] chan_sip.c: Header 11: (0) Apr 25 17:00:09 VERBOSE[2988723104] logger.c: --- (11 headers 0 lines) --- Apr 25 17:00:09 DEBUG[2988723104] chan_sip.c: = Found Their Call ID: 4f785bbb375a2e2016d0b326268ad1ec@10.10.250.62 Their Tag Our tag: as392cd96c Apr 25 17:00:09 DEBUG[2988723104] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #21 Apr 25 17:00:09 DEBUG[2988723104] chan_sip.c: Stopping retransmission on '4f785bbb375a2e2016d0b326268ad1ec@10.10.250.62' of Request 102: Match Found Apr 25 17:00:09 VERBOSE[2988723104] logger.c: Destroying call '4f785bbb375a2e2016d0b326268ad1ec@10.10.250.62' Apr 25 17:00:32 VERBOSE[3080002464] logger.c: -- Remote UNIX connection Apr 25 17:00:36 VERBOSE[2983873440] logger.c: Executing last minute cleanups Apr 25 17:00:36 VERBOSE[2983873440] logger.c: CHAN FAX: Stopping Fax Modem SLOT 0 Apr 25 17:00:36 VERBOSE[2983873440] logger.c: CHAN FAX: Stopping Fax Modem SLOT 1 Apr 25 17:00:36 DEBUG[2983873440] channel.c: Unregistering channel type 'Fax' Apr 25 17:00:36 VERBOSE[2983873440] logger.c: == Unregistered channel type 'Fax' Apr 25 17:00:36 VERBOSE[2983873440] logger.c: == Destroying musiconhold processes Apr 25 17:00:36 DEBUG[2983873440] callweaver.c: CallWeaver ending (0).