Hello all,
I have hylafax configured with t38modem and asterisk is configured as t38 gateway (setvar=FAXOPT(gateway)=yes).
Hylafax has an IP of 192.168.22.198 and asterisk 192.168.22.201
All received faxes are working with t38 protocol and almost all faxes going out also use t38 and work fine.
For some reason some specific fax machines failed to receive my faxes every time.
I know the fax machine is fully functional because it receives faxes other than from my hylafax.
The reason i get for failing is either BUSY Signal (which it’s not) or NO CARRIER.
The same fax machines can send faxes to hylafax with no problem.
I noticed that the faxes that are failing - t38modem talked to asterisk in g.711 and not in t38.
I tried all i can think off and will appreciate any ideas.
Topoligy:
PRI -> asterisk <-> SIP <-> t38modem -> Hylafax
Software:
Ubuntu 12.04 64 bit
T38modem 2.0.0
libopal3.10.4
ptlib-2.10.4
hylafax-6.0.5-5
asterisk 10.4.0
res_fax_spandsp.so (libspandsp.so.2.0.0)
T38modem command options:
t38modem -ttt -o /var/log/t38modem.log --no-h323 -u 9986 --sip-listen udp$192.168.22.198:6076 --sip-redundancy 3 --sip-old-asn --ptty +/dev/9986 --route modem:.=sip:@192.168.22.201 --route sip:.=modem:
(i tried using OPAL-Force-T38-Mode, OPAL-No-Force-T38-Mode and OPAL-Force-Fax-Mode )
Hylafax modem config:
SessionTracing: 0xFFF
RecvFileMode: 0600
LogFileMode: 0600
DeviceMode: 0600
TagLineFont: etc/lutRS18.pcf
GettyArgs: "-h %l dx_%s"
TagLineFormat: "From %%l|%c|Page %%P of %%T"
MaxRecvPages: 200
SpeakerVolume: off
ModemType: Class1 # use class 1 interface
ModemFlowControl: rtscts # default
ModemRevQueryCmd: AT+FREV?
Class1FrameOverhead: 2 # does not include FCS
Class1MsgRecvHackCmd: AT+FRS=1
Class1TCFRecvHack: Yes
Class1ECMSupport: No
ModemResetCmds: “AT#CID=10” # enable ANI/DNIS reporting T38
RingsBeforeAnswer: 2 # collect info between two RINGs
CallIDPattern: "NMBR = "
CallIDPattern: "NAME = "
CallIDPattern: "ANID = "
CallIDPattern: "USER = " # username provided by call
CallIDPattern: "PASS = " # password provided by call
CallIDPattern: "CDID = " # DID context in call
CallIDPattern: "NDID = "
ModemDialCmd: ATDV%s # user can override V by dial F
FaxRcvdCmd: bin/faxrcvd.php
DynamicConfig: bin/dynconf.php
UseJobTSI: true
Hylafax Log:
May 31 12:58:22 Fax-SRV FaxSend[16989]: MODEM VYACHESLAV FROLOV T38FAX/2.0.0
May 31 12:58:22 Fax-SRV FaxSend[16989]: SEND FAX: JOB 196 DEST 025871906 COMMID 000002954 DEVICE ‘/dev/9986’ FROM ‘Ben Kaplan emailaddress@example.com’ USER root
May 31 12:59:22 Fax-SRV FaxSend[16989]: SEND FAILED: JOB 196 DEST 025871906 ERR [2] No carrier detected
T38modem log file:
2012/05/31 12:59:46.435 Opal Liste…0xeeaf5700 SIP Sending PDU 200 OK (364 bytes) to: rem=udp$192.168.22.200:5060,local=udp$192.168.22.198:6069,if=192.168.22.198%eth0
2012/05/31 12:59:46.435 Opal Liste…0xeeaf5700 OpalUDP Setting interface to 192.168.22.198%eth0
2012/05/31 12:59:46.435 Opal Liste…0xeeaf5700 Opal Transport clean up on termination
2012/05/31 12:59:51.435 Housekeeper:0xeeb36700 SIP Set state Terminated_Success for SIP_PDU_Method<14> transaction id=z9hG4bK610cff45
2012/05/31 13:00:09.305 Opal Liste…0xeeaf5700 OpalUDP Binding to interface: 192.168.22.198:6069
2012/05/31 13:00:09.305 Opal Liste…0xeeaf5700 SIP PDU OPTIONS sip:192.168.22.198 received: rem=udp$192.168.22.201:5060,local=udp$192.168.22.198:6069,if=192.168.22.198%eth0
2012/05/31 13:00:09.306 Opal Liste…0xeeaf5700 SIP Sending PDU 200 OK (364 bytes) to: rem=udp$192.168.22.201:5060,local=udp$192.168.22.198:6069,if=192.168.22.198%eth0
2012/05/31 13:00:09.306 Opal Liste…0xeeaf5700 OpalUDP Setting interface to 192.168.22.198%eth0
2012/05/31 13:00:09.306 Opal Liste…0xeeaf5700 Opal Transport clean up on termination
2012/05/31 13:00:14.305 Housekeeper:0xeeb36700 SIP Set state Terminated_Success for SIP_PDU_Method<14> transaction id=z9hG4bK63c0ce74
2012/05/31 13:00:40.115 9979(i):36…0xdc0e0700 --> read ERROR -1 Input/output error
2012/05/31 13:00:40.115 9979(i):36…0xdc0e0700 --> Stopped
2012/05/31 13:00:40.115 9979(i):36…0xdc0e0700 PTLib Thread ended: name=“9979(i):3691906816:0xdc0e0700”, real=211.052, kernel=0.000 (0%), user=0.000 (0%), both=0.000 (0%)
2012/05/31 13:00:40.125 9979(o):36…0xdc09f700 <-- Stopped
2012/05/31 13:00:40.125 9979(o):36…0xdc09f700 PTLib Thread ended: name=“9979(o):3691640576:0xdc09f700”, real=211.063, kernel=0.000 (0%), user=0.000 (0%), both=0.000 (0%)
2012/05/31 13:00:40.135 9979(e):40…0xeeab4700 <-> Stopped
2012/05/31 13:00:40.135 9979(e):40…0xeeab4700 PTLib Thread ended: name=“9979(e):4004202240:0xeeab4700”, real=211.073, kernel=0.000 (0%), user=0.000 (0%), both=0.000 (0%)
2012/05/31 13:00:40.145 9979(i):36…0xdc09f700 RenameCurrentThread old ThreadName=InPty:0xdc09f700
2012/05/31 13:00:40.145 9979(i):36…0xdc09f700 --> Started
2012/05/31 13:00:40.145 9979(o):36…0xdc0e0700 RenameCurrentThread old ThreadName=OutPty:0xdc0e0700
2012/05/31 13:00:40.146 9979(o):36…0xdc0e0700 <-- Started
2012/05/31 13:00:40.145 9979(e):40…0xeeab4700 RenameCurrentThread old ThreadName=ModemEngine:0xeeab4700
2012/05/31 13:00:40.146 9979(e):40…0xeeab4700 <-> Started
2012/05/31 13:00:44.805 9979(e):40…0xeeab4700 --> ATZ
2012/05/31 13:00:44.806 9979(e):40…0xeeab4700 <-- {
0d 0a 4f 4b 0d 0a …OK… }
2012/05/31 13:00:46.434 Opal Liste…0xeeaf5700 OpalUDP Binding to interface: 192.168.22.198:6069
2012/05/31 13:00:46.435 Opal Liste…0xeeaf5700 SIP PDU OPTIONS sip:192.168.22.198 received: rem=udp$192.168.22.200:5060,local=udp$192.168.22.198:6069,if=192.168.22.198%eth0
2012/05/31 13:00:46.435 Opal Liste…0xeeaf5700 SIP Sending PDU 200 OK (364 bytes) to: rem=udp$192.168.22.200:5060,local=udp$192.168.22.198:6069,if=192.168.22.198%eth0
2012/05/31 13:00:46.436 Opal Liste…0xeeaf5700 OpalUDP Setting interface to 192.168.22.198%eth0
2012/05/31 13:00:46.436 Opal Liste…0xeeaf5700 Opal Transport clean up on termination
2012/05/31 13:00:47.908 9979(e):40…0xeeab4700 --> AT#CID=10
2012/05/31 13:00:47.908 9979(e):40…0xeeab4700 <-- {
0d 0a 4f 4b 0d 0a …OK… }
2012/05/31 13:00:48.005 9979(e):40…0xeeab4700 --> ATS0=0
2012/05/31 13:00:48.005 9979(e):40…0xeeab4700 <-- {
0d 0a 4f 4b 0d 0a …OK… }
2012/05/31 13:00:48.105 9979(e):40…0xeeab4700 --> ATE0
2012/05/31 13:00:48.105 9979(e):40…0xeeab4700 <-- {
0d 0a 4f 4b 0d 0a …OK… }
2012/05/31 13:00:48.205 9979(e):40…0xeeab4700 --> ATV1
2012/05/31 13:00:48.205 9979(e):40…0xeeab4700 <-- {
0d 0a 4f 4b 0d 0a …OK… }
2012/05/31 13:00:48.305 9979(e):40…0xeeab4700 --> ATQ0
2012/05/31 13:00:48.305 9979(e):40…0xeeab4700 <-- {
0d 0a 4f 4b 0d 0a …OK… }
2012/05/31 13:00:48.405 9979(e):40…0xeeab4700 --> ATS8=2
2012/05/31 13:00:48.405 9979(e):40…0xeeab4700 <-- {
0d 0a 4f 4b 0d 0a …OK… }
2012/05/31 13:00:48.505 9979(e):40…0xeeab4700 --> ATS7=60
2012/05/31 13:00:48.505 9979(e):40…0xeeab4700 <-- {
0d 0a 4f 4b 0d 0a …OK… }
2012/05/31 13:00:48.605 9979(e):40…0xeeab4700 --> AT+FCLASS=?
2012/05/31 13:00:48.605 9979(e):40…0xeeab4700 <-- {
0d 0a 31 2c 38 0d 0a 4f 4b 0d 0a …1,8…OK… }
2012/05/31 13:00:48.705 9979(e):40…0xeeab4700 --> AT+FCLASS=1
2012/05/31 13:00:48.705 9979(e):40…0xeeab4700 <-- {
0d 0a 4f 4b 0d 0a …OK… }
2012/05/31 13:00:48.805 9979(e):40…0xeeab4700 --> ATI3
2012/05/31 13:00:48.805 9979(e):40…0xeeab4700 <-- {
0d 0a 56 79 61 63 68 65 73 6c 61 76 20 46 72 6f …Vyacheslav Fro
6c 6f 76 0d 0a 4f 4b 0d 0a lov…OK… }
2012/05/31 13:00:48.905 9979(e):40…0xeeab4700 --> ATI0
2012/05/31 13:00:48.905 9979(e):40…0xeeab4700 <-- {
0d 0a 54 33 38 46 41 58 0d 0a 4f 4b 0d 0a …T38FAX…OK… }
2012/05/31 13:00:49.005 9979(e):40…0xeeab4700 --> AT+FREV?
2012/05/31 13:00:49.005 9979(e):40…0xeeab4700 <-- {
0d 0a 32 2e 30 2e 30 0d 0a 4f 4b 0d 0a …2.0.0…OK… }
2012/05/31 13:00:49.105 9979(e):40…0xeeab4700 --> AT+FTM=?
2012/05/31 13:00:49.105 9979(e):40…0xeeab4700 <-- {
0d 0a 32 34 2c 34 38 2c 37 32 2c 37 33 2c 37 34 …24,48,72,73,74
2c 39 36 2c 39 37 2c 39 38 2c 31 32 31 2c 31 32 ,96,97,98,121,12
32 2c 31 34 35 2c 31 34 36 0d 0a 4f 4b 0d 0a 2,145,146…OK… }
2012/05/31 13:00:49.205 9979(e):40…0xeeab4700 --> AT+FRM=?
2012/05/31 13:00:49.205 9979(e):40…0xeeab4700 <-- {
0d 0a 32 34 2c 34 38 2c 37 32 2c 37 33 2c 37 34 …24,48,72,73,74
2c 39 36 2c 39 37 2c 39 38 2c 31 32 31 2c 31 32 ,96,97,98,121,12
32 2c 31 34 35 2c 31 34 36 0d 0a 4f 4b 0d 0a 2,145,146…OK… }
2012/05/31 13:00:49.305 9979(e):40…0xeeab4700 --> ATM0
2012/05/31 13:00:49.305 9979(e):40…0xeeab4700 <-- {
0d 0a 4f 4b 0d 0a …OK… }
2012/05/31 13:00:49.406 9979(e):40…0xeeab4700 --> AT+FCLASS=1
2012/05/31 13:00:49.406 9979(e):40…0xeeab4700 <-- {
0d 0a 4f 4b 0d 0a …OK… }
2012/05/31 13:00:49.406 9979(e):40…0xeeab4700 --> ATDV025871906
2012/05/31 13:00:49.406 9979(e):40…0xeeab4700 Dial string: 025871906@LV - OK
2012/05/31 13:00:49.406 9979(e):40…0xeeab4700 ModemEndPoint::OnMyCallback command=dial extra=5
2012/05/31 13:00:49.406 9979(e):40…0xeeab4700 PseudoModemQ::Dequeue 9979
2012/05/31 13:00:49.406 9979(e):40…0xeeab4700 MyManager::OnMyCallback SetUpCall(modem:, 025871906@+/dev/9979)
2012/05/31 13:00:49.407 9979(e):40…0xeeab4700 OpalMan Set up call from modem: to 025871906@+/dev/9979
2012/05/31 13:00:49.407 9979(e):40…0xeeab4700 Call Created Call[C7d7890f51]
2012/05/31 13:00:49.407 9979(e):40…0xeeab4700 OpalMan Set up connection to "modem:"
2012/05/31 13:00:49.407 9979(e):40…0xeeab4700 ModemEndPoint::MakeConnection modem:
2012/05/31 13:00:49.407 9979(e):40…0xeeab4700 OpalCon Created connection Call[C7d7890f51]-EP[modem:/C7d7890f51/0]
2012/05/31 13:00:49.407 9979(e):40…0xeeab4700 ModemConnection::SetUpConnection Call[C7d7890f51]-EP[modem:/C7d7890f51/0]
2012/05/31 13:00:49.407 9979(e):40…0xeeab4700 OpalCon SetPhase from UninitialisedPhase to SetUpPhase for Call[C7d7890f51]-EP[modem:/C7d7890f51/0]
2012/05/31 13:00:49.408 9979(e):40…0xeeab4700 OpalMan OnIncoming connection Call[C7d7890f51]-EP[modem:/C7d7890f51/0]
2012/05/31 13:00:49.408 9979(e):40…0xeeab4700 OpalMan Set up connection to "sip:025871906@192.168.22.201"
2012/05/31 13:00:49.408 9979(e):40…0xeeab4700 MySIPEndPoint::CreateConnection for Call[C7d7890f51]
2012/05/31 13:00:49.408 9979(e):40…0xeeab4700 OpalCon Created connection Call[C7d7890f51]-EP[c235ea2a-75a9-e111-8ae0-005056800015]
2012/05/31 13:00:49.410 9979(e):40…0xeeab4700 Call[C7d7890f51] from modem:9979 to 025871906@+/dev/9979, route to sip:025871906@192.168.22.201
2012/05/31 13:00:49.410 9979(e):40…0xeeab4700 Outgoing call routed to sip:025871906@192.168.22.201 for Call[C7d7890f51]-EP[modem:/C7d7890f51/0]
2012/05/31 13:00:49.410 9979(e):40…0xeeab4700 Call OnSetUp Call[C7d7890f51]-EP[modem:/C7d7890f51/0]
2012/05/31 13:00:49.410 9979(e):40…0xeeab4700 MySIPConnection::SetUpConnection Call[C7d7890f51]-EP[c235ea2a-75a9-e111-8ae0-005056800015] name=9979
2012/05/31 13:00:49.410 9979(e):40…0xeeab4700 SIP SetUpConnection: sip:025871906@192.168.22.201
2012/05/31 13:00:49.410 9979(e):40…0xeeab4700 OpalUDP Binding to interface: 192.168.22.198:6069
2012/05/31 13:00:49.410 9979(e):40…0xeeab4700 OpalUDP Started connect to 192.168.22.201:5060
2012/05/31 13:00:49.411 9979(e):40…0xeeab4700 ModemEndPoint::GetMediaFormats
2012/05/31 13:00:49.416 9979(e):40…0xeeab4700 MySIPConnection::GetLocalMediaFormats Remove GSM-AMR
2012/05/31 13:00:49.416 9979(e):40…0xeeab4700 MySIPConnection::GetLocalMediaFormats Remove GSM-06.10
2012/05/31 13:00:49.416 9979(e):40…0xeeab4700 MySIPConnection::GetLocalMediaFormats Remove G.726-40k
2012/05/31 13:00:49.416 9979(e):40…0xeeab4700 MySIPConnection::GetLocalMediaFormats Remove G.726-32k
2012/05/31 13:00:49.416 9979(e):40…0xeeab4700 MySIPConnection::GetLocalMediaFormats Remove G.726-24k
2012/05/31 13:00:49.416 9979(e):40…0xeeab4700 MySIPConnection::GetLocalMediaFormats Remove G.726-16k
2012/05/31 13:00:49.416 9979(e):40…0xeeab4700 MySIPConnection::GetLocalMediaFormats Remove LPC-10
2012/05/31 13:00:49.416 9979(e):40…0xeeab4700 MySIPConnection::GetLocalMediaFormats Remove MS-GSM
2012/05/31 13:00:49.416 9979(e):40…0xeeab4700 MySIPConnection::GetLocalMediaFormats Remove MS-IMA-ADPCM
2012/05/31 13:00:49.417 9979(e):40…0xeeab4700 MySIPConnection::GetLocalMediaFormats Remove SILK-8
2012/05/31 13:00:49.417 9979(e):40…0xeeab4700 MySIPConnection::GetLocalMediaFormats Remove SpeexIETFNarrow-11k
2012/05/31 13:00:49.417 9979(e):40…0xeeab4700 MySIPConnection::GetLocalMediaFormats Remove SpeexIETFNarrow-15k
2012/05/31 13:00:49.417 9979(e):40…0xeeab4700 MySIPConnection::GetLocalMediaFormats Remove SpeexIETFNarrow-18.2k
2012/05/31 13:00:49.417 9979(e):40…0xeeab4700 MySIPConnection::GetLocalMediaFormats Remove SpeexIETFNarrow-24.6k
2012/05/31 13:00:49.417 9979(e):40…0xeeab4700 MySIPConnection::GetLocalMediaFormats Remove SpeexIETFNarrow-5.95k
2012/05/31 13:00:49.417 9979(e):40…0xeeab4700 MySIPConnection::GetLocalMediaFormats Remove SpeexIETFNarrow-8k
2012/05/31 13:00:49.417 9979(e):40…0xeeab4700 MySIPConnection::GetLocalMediaFormats Remove SpeexNB
2012/05/31 13:00:49.417 9979(e):40…0xeeab4700 MySIPConnection::GetLocalMediaFormats Remove SpeexWNarrow-8k
2012/05/31 13:00:49.419 9979(e):40…0xeeab4700 SIP Creating INVITE request
2012/05/31 13:00:49.419 9979(e):40…0xeeab4700 SIP Offering media type audio in SDP
2012/05/31 13:00:49.419 9979(e):40…0xeeab4700 Call IsMediaBypassPossible Call[C7d7890f51]-EP[c235ea2a-75a9-e111-8ae0-005056800015] session 1
2012/05/31 13:00:49.419 9979(e):40…0xeeab4700 OpalMan IsMediaBypassPossible: session 1
2012/05/31 13:00:49.419 9979(e):40…0xeeab4700 RTP Cannot find media session 1
2012/05/31 13:00:49.420 9979(e):40…0xeeab4700 RTP Cannot find RTP session 1
2012/05/31 13:00:49.420 9979(e):40…0xeeab4700 RTP_UDP Session 1 created: 192.168.22.198:5000-5001 ssrc=1197576518
2012/05/31 13:00:49.420 9979(e):40…0xeeab4700 RTP Creating new session RTP_UDP
2012/05/31 13:00:49.420 9979(e):40…0xeeab4700 RTP Found existing media session 1
2012/05/31 13:00:49.421 9979(e):40…0xeeab4700 SIP No media formats of type video, not adding SDP
2012/05/31 13:00:49.421 9979(e):40…0xeeab4700 SIP Transaction remote address is udp$192.168.22.201:5060
2012/05/31 13:00:49.422 9979(e):40…0xeeab4700 SIP Sending PDU INVITE sip:025871906@192.168.22.201 (1158 bytes) to: rem=udp$192.168.22.201:5060,local=udp$192.168.22.198:6069,if=192.168.22.198%eth0
2012/05/31 13:00:49.423 9979(e):40…0xeeab4700 OpalUDP Setting interface to 192.168.22.198%eth0
2012/05/31 13:00:49.423 9979(e):40…0xeeab4700 OpalCon SetPhase from UninitialisedPhase to SetUpPhase for Call[C7d7890f51]-EP[c235ea2a-75a9-e111-8ae0-005056800015]
2012/05/31 13:00:49.423 9979(e):40…0xeeab4700 OpalCon OnSetUpConnectionCall[C7d7890f51]-EP[c235ea2a-75a9-e111-8ae0-005056800015]
2012/05/31 13:00:49.423 9979(e):40…0xeeab4700 OpalEP OnSetUpConnection Call[C7d7890f51]-EP[c235ea2a-75a9-e111-8ae0-005056800015]
2012/05/31 13:00:49.423 9979(e):40…0xeeab4700 ModemEndPoint::OnMyCallback request={
calltoken=modem:/C7d7890f51/0
localpartyname=
command=dial
response=confirm
number=025871906
modemtoken=9979
}
2012/05/31 13:00:49.426 Opal Liste…0xeeaf5700 OpalUDP Binding to interface: 192.168.22.198:6069
2012/05/31 13:00:49.426 Opal Liste…0xeeaf5700 SIP PDU 100 Trying received: rem=udp$192.168.22.201:5060,local=udp$192.168.22.198:6069,if=192.168.22.198%eth0
2012/05/31 13:00:49.427 Opal Liste…0xeeaf5700 Opal Transport clean up on termination
2012/05/31 13:00:49.427 Pool:0xdc05e700 SIP Handling PDU “1 INVITE <100>” for transaction=z9hG4bK0ecaeb2a-75a9-e111-8ae0-005056800015
2012/05/31 13:00:49.427 Pool:0xdc05e700 SIP INVITE transaction id=z9hG4bK0ecaeb2a-75a9-e111-8ae0-005056800015 proceeding.
2012/05/31 13:00:49.427 Pool:0xdc05e700 SIP Received Trying response
2012/05/31 13:00:49.427 Pool:0xdc05e700 OpalCon SetPhase from SetUpPhase to ProceedingPhase for Call[C7d7890f51]-EP[c235ea2a-75a9-e111-8ae0-005056800015]
2012/05/31 13:00:49.427 Pool:0xdc05e700 OpalMan OnProceeding Call[C7d7890f51]-EP[c235ea2a-75a9-e111-8ae0-005056800015]
2012/05/31 13:00:49.427 Pool:0xdc05e700 Call OnProceeding Call[C7d7890f51]-EP[c235ea2a-75a9-e111-8ae0-005056800015]
2012/05/31 13:00:49.512 Opal Liste…0xeeaf5700 OpalUDP Binding to interface: 192.168.22.198:6069
2012/05/31 13:00:49.513 Opal Liste…0xeeaf5700 SIP PDU 100 Trying received: rem=udp$192.168.22.201:5060,local=udp$192.168.22.198:6069,if=192.168.22.198%eth0
2012/05/31 13:00:49.513 Opal Liste…0xeeaf5700 Opal Transport clean up on termination
2012/05/31 13:00:49.513 Pool:0xdc05e700 SIP Handling PDU “1 INVITE <100>” for transaction=z9hG4bK0ecaeb2a-75a9-e111-8ae0-005056800015
2012/05/31 13:00:49.513 Pool:0xdc05e700 SIP INVITE transaction id=z9hG4bK0ecaeb2a-75a9-e111-8ae0-005056800015 proceeding.
2012/05/31 13:00:49.513 Pool:0xdc05e700 SIP Received Trying response
2012/05/31 13:00:50.170 Opal Liste…0xeeaf5700 OpalUDP Binding to interface: 192.168.22.198:6069
2012/05/31 13:00:50.171 Opal Liste…0xeeaf5700 SIP PDU 180 Ringing received: rem=udp$192.168.22.201:5060,local=udp$192.168.22.198:6069,if=192.168.22.198%eth0
2012/05/31 13:00:50.171 Opal Liste…0xeeaf5700 Opal Transport clean up on termination
2012/05/31 13:00:50.171 Opal Liste…0xeeaf5700 OpalUDP Binding to interface: 192.168.22.198:6069
2012/05/31 13:00:50.171 Opal Liste…0xeeaf5700 SIP PDU 183 Session Progress received: rem=udp$192.168.22.201:5060,local=udp$192.168.22.198:6069,if=192.168.22.198%eth0
2012/05/31 13:00:50.171 Opal Liste…0xeeaf5700 Opal Transport clean up on termination
2012/05/31 13:00:50.171 Pool:0xdc05e700 SIP Handling PDU “1 INVITE <180>” for transaction=z9hG4bK0ecaeb2a-75a9-e111-8ae0-005056800015
2012/05/31 13:00:50.172 Pool:0xdc05e700 SIP INVITE transaction id=z9hG4bK0ecaeb2a-75a9-e111-8ae0-005056800015 proceeding.
2012/05/31 13:00:50.172 Pool:0xdc05e700 SIP Received Ringing response
2012/05/31 13:00:50.172 Pool:0xdc05e700 OpalCon SetPhase from ProceedingPhase to AlertingPhase for Call[C7d7890f51]-EP[c235ea2a-75a9-e111-8ae0-005056800015]
2012/05/31 13:00:50.172 Pool:0xdc05e700 OpalMan OnAlerting Call[C7d7890f51]-EP[c235ea2a-75a9-e111-8ae0-005056800015]
2012/05/31 13:00:50.172 Pool:0xdc05e700 Call OnAlerting Call[C7d7890f51]-EP[c235ea2a-75a9-e111-8ae0-005056800015]
2012/05/31 13:00:50.172 Pool:0xdc05e700 ModemConnection::SetAlerting Call[C7d7890f51]-EP[modem:/C7d7890f51/0] sip:025871906@192.168.22.201 0
2012/05/31 13:00:50.172 Pool:0xdc05e700 OpalCon SetPhase from SetUpPhase to AlertingPhase for Call[C7d7890f51]-EP[modem:/C7d7890f51/0]
2012/05/31 13:00:50.172 Pool:0xdc05e700 ModemEngineBody::Request: stConnectWait request={
calltoken=modem:/C7d7890f51/0
command=alerting
}
2012/05/31 13:00:50.172 Pool:0xdc05e700 OpalCon Media stream threads started for Call[C7d7890f51]-EP[modem:/C7d7890f51/0]
2012/05/31 13:00:50.172 Pool:0xdc05e700 OpalCon Media stream threads started for Call[C7d7890f51]-EP[c235ea2a-75a9-e111-8ae0-005056800015]
2012/05/31 13:00:50.172 Pool:0xdc05e700 SIP Handling PDU “1 INVITE <183>” for transaction=z9hG4bK0ecaeb2a-75a9-e111-8ae0-005056800015
2012/05/31 13:00:50.173 Pool:0xdc05e700 SDP Parsed final media session with 6 ‘audio’ formats
2012/05/31 13:00:50.173 Pool:0xdc05e700 SIP RTP payload type PCMU matched to codec G.711-uLaw-64k
2012/05/31 13:00:50.173 Pool:0xdc05e700 SIP RTP payload type GSM matched to codec GSM-06.10
2012/05/31 13:00:50.173 Pool:0xdc05e700 SIP RTP payload type PCMA matched to codec G.711-ALaw-64k
2012/05/31 13:00:50.174 Pool:0xdc05e700 SIP RTP payload type speex matched to codec SpeexNB
2012/05/31 13:00:50.174 Pool:0xdc05e700 SIP RTP payload type G726-32 matched to codec G.726-32k
2012/05/31 13:00:50.174 Pool:0xdc05e700 SIP RTP payload type telephone-event matched to codec UserInput/RFC2833
2012/05/31 13:00:50.174 Pool:0xdc05e700 SIP INVITE transaction id=z9hG4bK0ecaeb2a-75a9-e111-8ae0-005056800015 proceeding.
2012/05/31 13:00:50.174 Pool:0xdc05e700 SIP Received Session Progress response
2012/05/31 13:00:50.174 Pool:0xdc05e700 Call IsMediaBypassPossible Call[C7d7890f51]-EP[c235ea2a-75a9-e111-8ae0-005056800015] session 1
2012/05/31 13:00:50.174 Pool:0xdc05e700 OpalMan IsMediaBypassPossible: session 1
2012/05/31 13:00:50.174 Pool:0xdc05e700 RTP Found existing RTP session 1
2012/05/31 13:00:50.174 Pool:0xdc05e700 RTP_UDP Session 1, SetRemoteSocketInfo: data channel, new=192.168.22.201:15840, local=192.168.22.198:5000-5001, remote=0.0.0.0:0-0
2012/05/31 13:00:50.174 Pool:0xdc05e700 RTP Found existing media session 1
2012/05/31 13:00:50.174 Pool:0xdc05e700 Call OpenSourceMediaStreams open for audio session 1 on Call[C7d7890f51]-EP[c235ea2a-75a9-e111-8ae0-005056800015]
2012/05/31 13:00:50.174 Pool:0xdc05e700 ModemEndPoint::GetMediaFormats
2012/05/31 13:00:50.175 Pool:0xdc05e700 MySIPConnection::GetMediaFormats Remove GSM-06.10
2012/05/31 13:00:50.175 Pool:0xdc05e700 MySIPConnection::GetMediaFormats Remove SpeexNB
2012/05/31 13:00:50.175 Pool:0xdc05e700 MySIPConnection::GetMediaFormats Remove G.726-32k
2012/05/31 13:00:50.176 Pool:0xdc05e700 Call Selected media formats G.711-uLaw-64k -> PCM-16
2012/05/31 13:00:50.176 Pool:0xdc05e700 Call IsMediaBypassPossible Call[C7d7890f51]-EP[c235ea2a-75a9-e111-8ae0-005056800015] session 1
2012/05/31 13:00:50.176 Pool:0xdc05e700 OpalMan IsMediaBypassPossible: session 1
2012/05/31 13:00:50.176 Pool:0xdc05e700 RTP Found existing RTP session 1
2012/05/31 13:00:50.176 Pool:0xdc05e700 RTP Found existing media session 1
2012/05/31 13:00:50.176 Pool:0xdc05e700 RTP_UDP Session 1 reopened for reading
2012/05/31 13:00:50.176 Pool:0xdc05e700 RTP Found existing RTP session 1
2012/05/31 13:00:50.176 Pool:0xdc05e700 OpalMan OnOpenMediaStream Call[C7d7890f51]-EP[c235ea2a-75a9-e111-8ae0-005056800015],OpalRTPMediaStream-Source-G.711-uLaw-64k
2012/05/31 13:00:50.176 Pool:0xdc05e700 OpalCon Opened source stream C7d7890f51_1 with format G.711-uLaw-64k
2012/05/31 13:00:50.176 Pool:0xdc05e700 ModemConnection::CreateMediaStream Call[C7d7890f51]-EP[modem:/C7d7890f51/0] mediaFormat=PCM-16 sessionID=1 isSource=0
2012/05/31 13:00:50.176 Pool:0xdc05e700 9979 AudioEngine AudioEngine
2012/05/31 13:00:50.176 Pool:0xdc05e700 9979 AudioEngine Attach
2012/05/31 13:00:50.176 Pool:0xdc05e700 9979 AudioEngine OnAttach Attached
2012/05/31 13:00:50.176 Pool:0xdc05e700 9979 AudioEngine OnResetModemState
2012/05/31 13:00:50.176 Pool:0xdc05e700 9979 AudioEngine ChangeModemClass to mcFax
2012/05/31 13:00:50.176 Pool:0xdc05e700 9979 AudioEngine OnChangeModemClass to mcFax
2012/05/31 13:00:50.176 Pool:0xdc05e700 9979 AudioEngine SendOnIdle dtNone
2012/05/31 13:00:50.176 Pool:0xdc05e700 ModemEngineBody::_AttachEngine Attached mceAudio
2012/05/31 13:00:50.176 Pool:0xdc05e700 ModemEngineBody::NewPtrEngine created pointer for engine mceAudio
2012/05/31 13:00:50.176 Pool:0xdc05e700 AudioModemMediaStream::Open AudioModemMediaStream-Sink-PCM-16
2012/05/31 13:00:50.176 Pool:0xdc05e700 9979 AudioEngine OpenIn: open 0x7fd8ac00d200
2012/05/31 13:00:50.176 Pool:0xdc05e700 OpalMan OnOpenMediaStream Call[C7d7890f51]-EP[modem:/C7d7890f51/0],AudioModemMediaStream-Sink-PCM-16
2012/05/31 13:00:50.176 Pool:0xdc05e700 OpalCon Opened sink stream C7d7890f51_1 with format PCM-16
2012/05/31 13:00:50.177 Pool:0xdc05e700 Patch Created Sink: format=PCM-16
2012/05/31 13:00:50.177 Pool:0xdc05e700 Codec G711-uLaw-64k decoder created
2012/05/31 13:00:50.177 Pool:0xdc05e700 Patch Added media stream sink AudioModemMediaStream-Sink-PCM-16 using transcoder G.711-uLaw-64k->PCM-16, data size=3840
2012/05/31 13:00:50.177 Pool:0xdc05e700 Media RTP data size cannot be changed to 160, fixed at 2048
2012/05/31 13:00:50.177 Pool:0xdc05e700 OpalCon Sink stream of connection Call[C7d7890f51]-EP[modem:/C7d7890f51/0] uses patch Patch[0x7fd8ac00d570] OpalRTPMediaStream-Source-G.711-uLaw-64k -> AudioModemMediaStream-Sink-PCM-16
2012/05/31 13:00:50.177 Pool:0xdc05e700 OpalCon Source stream of connection Call[C7d7890f51]-EP[c235ea2a-75a9-e111-8ae0-005056800015] uses patch Patch[0x7fd8ac00d570] OpalRTPMediaStream-Source-G.711-uLaw-64k -> AudioModemMediaStream-Sink-PCM-16
2012/05/31 13:00:50.177 Pool:0xdc05e700 RTPCon Adding RFC2833 receive handler
2012/05/31 13:00:50.177 Pool:0xdc05e700 RTPCon Adding Cisco NSE receive handler
2012/05/31 13:00:50.178 Media Patch:0xd744c700 RTP_UDP Session 1, flushed 34 RTP data packets on startup
2012/05/31 13:00:50.178 Pool:0xdc05e700 Call OpenSourceMediaStreams open for audio session 1 on Call[C7d7890f51]-EP[modem:/C7d7890f51/0]
2012/05/31 13:00:50.178 Pool:0xdc05e700 MySIPConnection::GetMediaFormats Remove GSM-06.10
2012/05/31 13:00:50.178 Pool:0xdc05e700 MySIPConnection::GetMediaFormats Remove SpeexNB
2012/05/31 13:00:50.178 Pool:0xdc05e700 MySIPConnection::GetMediaFormats Remove G.726-32k
2012/05/31 13:00:50.178 Pool:0xdc05e700 ModemEndPoint::GetMediaFormats
2012/05/31 13:00:50.179 Pool:0xdc05e700 Call Selected media formats PCM-16 -> G.711-uLaw-64k
2012/05/31 13:00:50.179 Pool:0xdc05e700 ModemConnection::CreateMediaStream Call[C7d7890f51]-EP[modem:/C7d7890f51/0] mediaFormat=PCM-16 sessionID=1 isSource=1
2012/05/31 13:00:50.179 Pool:0xdc05e700 9979 AudioEngine SendOnIdle dtNone
2012/05/31 13:00:50.179 Pool:0xdc05e700 ModemEngineBody::_AttachEngine Attached mceAudio
2012/05/31 13:00:50.179 Pool:0xdc05e700 ModemEngineBody::NewPtrEngine created pointer for engine mceAudio
2012/05/31 13:00:50.179 Pool:0xdc05e700 AudioModemMediaStream::Open AudioModemMediaStream-Source-PCM-16
2012/05/31 13:00:50.179 Pool:0xdc05e700 9979 AudioEngine OpenOut: open 0x7fd8ac010a50
2012/05/31 13:00:50.179 Pool:0xdc05e700 OpalMan OnOpenMediaStream Call[C7d7890f51]-EP[modem:/C7d7890f51/0],AudioModemMediaStream-Source-PCM-16
2012/05/31 13:00:50.179 Pool:0xdc05e700 OpalCon Opened source stream C7d7890f51_1 with format PCM-16
2012/05/31 13:00:50.179 Pool:0xdc05e700 Call IsMediaBypassPossible Call[C7d7890f51]-EP[c235ea2a-75a9-e111-8ae0-005056800015] session 1
2012/05/31 13:00:50.179 Pool:0xdc05e700 OpalMan IsMediaBypassPossible: session 1
2012/05/31 13:00:50.179 Pool:0xdc05e700 RTP Found existing RTP session 1
2012/05/31 13:00:50.179 Pool:0xdc05e700 RTP Found existing media session 1
2012/05/31 13:00:50.180 Pool:0xdc05e700 RTP_UDP Session 1 reopened for writing
2012/05/31 13:00:50.180 Pool:0xdc05e700 RTP Found existing RTP session 1
2012/05/31 13:00:50.180 Pool:0xdc05e700 OpalMan OnOpenMediaStream Call[C7d7890f51]-EP[c235ea2a-75a9-e111-8ae0-005056800015],OpalRTPMediaStream-Sink-G.711-uLaw-64k
2012/05/31 13:00:50.180 Pool:0xdc05e700 OpalCon Opened sink stream C7d7890f51_1 with format G.711-uLaw-64k
2012/05/31 13:00:50.180 Pool:0xdc05e700 Patch Created Sink: format=G.711-uLaw-64k
2012/05/31 13:00:50.180 Pool:0xdc05e700 Codec G711-uLaw-64k encoder created
2012/05/31 13:00:50.180 Pool:0xdc05e700 Media RTP data size cannot be changed to 1920, fixed at 528
2012/05/31 13:00:50.180 Pool:0xdc05e700 Patch Added media stream sink OpalRTPMediaStream-Sink-G.711-uLaw-64k using transcoder PCM-16->G.711-uLaw-64k, data size=528
2012/05/31 13:00:50.180 Pool:0xdc05e700 OpalCon Source stream of connection Call[C7d7890f51]-EP[modem:/C7d7890f51/0] uses patch Patch[0x7fd8ac011140] AudioModemMediaStream-Source-PCM-16 -> OpalRTPMediaStream-Sink-G.711-uLaw-64k
2012/05/31 13:00:50.180 Pool:0xdc05e700 OpalCon Sink stream of connection Call[C7d7890f51]-EP[c235ea2a-75a9-e111-8ae0-005056800015] uses patch Patch[0x7fd8ac011140] AudioModemMediaStream-Source-PCM-16 -> OpalRTPMediaStream-Sink-G.711-uLaw-64k
2012/05/31 13:00:50.180 Media Patch:0xd740b700 RTP Session 1, first sent data: ver=2 pt=PCMU psz=160 m=1 x=0 seq=14548 ts=0 src=47619146 ccnt=0
2012/05/31 13:00:50.181 Pool:0xdc05e700 SIP Queueing re-INVITE to resolve multiple codecs in answer
2012/05/31 13:00:50.182 Pool:0xdc05e700 SIP Creating INVITE request
2012/05/31 13:00:50.182 Pool:0xdc05e700 SIP Offering media type audio in SDP
2012/05/31 13:00:50.182 Pool:0xdc05e700 Call IsMediaBypassPossible Call[C7d7890f51]-EP[c235ea2a-75a9-e111-8ae0-005056800015] session 1
2012/05/31 13:00:50.182 Pool:0xdc05e700 OpalMan IsMediaBypassPossible: session 1
2012/05/31 13:00:50.182 Pool:0xdc05e700 RTP Found existing media session 1
2012/05/31 13:00:50.182 Pool:0xdc05e700 RTP Found existing RTP session 1
2012/05/31 13:00:50.182 Pool:0xdc05e700 OpalCon Media stream threads started for Call[C7d7890f51]-EP[modem:/C7d7890f51/0]
2012/05/31 13:00:50.182 Pool:0xdc05e700 OpalCon Media stream threads started for Call[C7d7890f51]-EP[c235ea2a-75a9-e111-8ae0-005056800015]
2012/05/31 13:00:50.198 Media Patch:0xd744c700 RTP Session 1, first receive data: ver=2 pt=PCMU psz=160 m=0 x=0 seq=155 ts=5600 src=7b9bafd5 ccnt=0
2012/05/31 13:00:51.436 Housekeeper:0xeeb36700 SIP Set state Terminated_Success for SIP_PDU_Method<14> transaction id=z9hG4bK0a4dfcd2
2012/05/31 13:00:52.180 Media Patch:0xd740b700 RTP Session 1, transmit statistics: packets=101 octets=16160 avgTime=20 maxTime=21 minTime=19
2012/05/31 13:00:54.180 Media Patch:0xd740b700 RTP Session 1, transmit statistics: packets=201 octets=32160 avgTime=19 maxTime=21 minTime=19
2012/05/31 13:00:54.518 Media Patch:0xd744c700 RTP Session 1, OnRxSenderReport: ssrc=2073800661 ntp=2012/5/31-13:0:58.899173 rtp=40160 psent=251 osent=40160
RR: ssrc=1197576518 fraction=0 lost=0 last_seq=14764 jitter=1 lsr=0.000 dlsr=19960:44:19.721
2012/05/31 13:00:54.518 Media Patch:0xd744c700 RTP Session 1, OnSourceDescription: 1 entries
ssrc=2073800661
item[0]: type=CNAME data=""
2012/05/31 13:00:56.180 Media Patch:0xd740b700 RTP Session 1, transmit statistics: packets=301 octets=48160 avgTime=20 maxTime=21 minTime=19
2012/05/31 13:00:58.180 Media Patch:0xd740b700 RTP Session 1, transmit statistics: packets=401 octets=64160 avgTime=20 maxTime=21 minTime=19
2012/05/31 13:00:59.518 Media Patch:0xd744c700 RTP Session 1, OnRxSenderReport: ssrc=2073800661 ntp=2012/5/31-13:1:3.899210 rtp=80160 psent=501 osent=80160
RR: ssrc=1197576518 fraction=0 lost=0 last_seq=15014 jitter=1 lsr=0.000 dlsr=19966:42:18.817
2012/05/31 13:00:59.518 Media Patch:0xd744c700 RTP Session 1, OnSourceDescription: 1 entries
ssrc=2073800661
item[0]: type=CNAME data=""
2012/05/31 13:01:00.180 Media Patch:0xd740b700 RTP Session 1, transmit statistics: packets=501 octets=80160 avgTime=20 maxTime=21 minTime=18
2012/05/31 13:01:01.420 Media Patch:0xd744c700 RTP Session 1, SentSenderReport: ssrc=1197576518 ntp=3547447261.1804738142 rtp=0 psent=563 osent=90080
2012/05/31 13:01:01.420 Media Patch:0xd744c700 RTP Session 1, SentReceiverReport: ssrc=2073800661 fraction=0 lost=0 last_seq=0 jitter=0 lsr=3219121701 dlsr=124649
2012/05/31 13:01:01.420 Media Patch:0xd744c700 RTP Session 1, sending SDES: root@Fax-SRV
2012/05/31 13:01:01.420 Media Patch:0xd744c700 RTP Session 1, SentExtendedReport: ssrc=1197576518 loss_rate=0 discard_rate=0 burst_density=128 gap_density=0 burst_duration=11997 gap_duration=1 round_trip_delay=51415 end_system_delay=0 gmin=16 r_factor=94 mos_lq=45 mos_cq=45 jb_nominal_delay=0 jb_maximum_delay=0 jb_absolute_delay=0
2012/05/31 13:01:02.179 Media Patch:0xd740b700 RTP Session 1, transmit statistics: packets=601 octets=96160 avgTime=19 maxTime=21 minTime=19
2012/05/31 13:01:04.180 Media Patch:0xd740b700 RTP Session 1, transmit statistics: packets=701 octets=112160 avgTime=20 maxTime=21 minTime=19
2012/05/31 13:01:04.517 Media Patch:0xd744c700 RTP Session 1, OnRxSenderReport: ssrc=2073800661 ntp=2012/5/31-13:1:8.899209 rtp=120000 psent=750 osent=120000
RR: ssrc=1197576518 fraction=0 lost=0 last_seq=15264 jitter=1 lsr=894:09:19.250 dlsr=3:41:41.448
2012/05/31 13:01:04.518 Media Patch:0xd744c700 RTP Session 1, OnSourceDescription: 1 entries
ssrc=2073800661
item[0]: type=CNAME data=""
2012/05/31 13:01:06.180 Media Patch:0xd740b700 RTP Session 1, transmit statistics: packets=801 octets=128160 avgTime=20 maxTime=21 minTime=19
2012/05/31 13:01:08.180 Media Patch:0xd740b700 RTP Session 1, transmit statistics: packets=901 octets=144160 avgTime=19 maxTime=21 minTime=19
2012/05/31 13:01:09.306 Opal Liste…0xeeaf5700 OpalUDP Binding to interface: 192.168.22.198:6069
2012/05/31 13:01:09.306 Opal Liste…0xeeaf5700 SIP PDU OPTIONS sip:192.168.22.198 received: rem=udp$192.168.22.201:5060,local=udp$192.168.22.198:6069,if=192.168.22.198%eth0
2012/05/31 13:01:09.307 Opal Liste…0xeeaf5700 SIP Sending PDU 200 OK (364 bytes) to: rem=udp$192.168.22.201:5060,local=udp$192.168.22.198:6069,if=192.168.22.198%eth0
2012/05/31 13:01:09.307 Opal Liste…0xeeaf5700 OpalUDP Setting interface to 192.168.22.198%eth0
2012/05/31 13:01:09.307 Opal Liste…0xeeaf5700 Opal Transport clean up on termination
2012/05/31 13:01:09.517 Media Patch:0xd744c700 RTP Session 1, OnRxSenderReport: ssrc=2073800661 ntp=2012/5/31-13:1:13.899158 rtp=160000 psent=1000 osent=160000
RR: ssrc=1197576518 fraction=0 lost=0 last_seq=15514 jitter=1 lsr=894:09:19.250 dlsr=9:39:36.285
2012/05/31 13:01:09.517 Media Patch:0xd744c700 RTP Session 1, OnSourceDescription: 1 entries
ssrc=2073800661
item[0]: type=CNAME data=""
2012/05/31 13:01:10.180 Media Patch:0xd740b700 RTP Session 1, transmit statistics: packets=1001 octets=160160 avgTime=20 maxTime=21 minTime=19
2012/05/31 13:01:12.180 Media Patch:0xd740b700 RTP Session 1, transmit statistics: packets=1101 octets=176160 avgTime=20 maxTime=21 minTime=19
2012/05/31 13:01:14.180 Media Patch:0xd740b700 RTP Session 1, transmit statistics: packets=1201 octets=192160 avgTime=20 maxTime=21 minTime=19
2012/05/31 13:01:14.306 Housekeeper:0xeeb36700 SIP Set state Terminated_Success for SIP_PDU_Method<14> transaction id=z9hG4bK37d00e28
2012/05/31 13:01:14.516 Media Patch:0xd744c700 RTP Session 1, OnRxSenderReport: ssrc=2073800661 ntp=2012/5/31-13:1:18.898230 rtp=200000 psent=1250 osent=200000
RR: ssrc=1197576518 fraction=0 lost=0 last_seq=15764 jitter=1 lsr=894:09:19.250 dlsr=15:37:26.861
2012/05/31 13:01:14.516 Media Patch:0xd744c700 RTP Session 1, OnSourceDescription: 1 entries
ssrc=2073800661
item[0]: type=CNAME data=""
2012/05/31 13:01:16.180 Media Patch:0xd740b700 RTP Session 1, transmit statistics: packets=1301 octets=208160 avgTime=20 maxTime=21 minTime=19
2012/05/31 13:01:17.296 Media Patch:0xd744c700 RTP Session 1, SentSenderReport: ssrc=1197576518 ntp=3547447277.1271367520 rtp=0 psent=1356 osent=216960
2012/05/31 13:01:17.296 Media Patch:0xd744c700 RTP Session 1, SentReceiverReport: ssrc=2073800661 fraction=0 lost=0 last_seq=717 jitter=0 lsr=3220104677 dlsr=182124
2012/05/31 13:01:17.296 Media Patch:0xd744c700 RTP Session 1, sending SDES: root@Fax-SRV
2012/05/31 13:01:17.296 Media Patch:0xd744c700 RTP Session 1, SentExtendedReport: ssrc=1197576518 loss_rate=0 discard_rate=0 burst_density=128 gap_density=0 burst_duration=27857 gap_duration=9 round_trip_delay=1 end_system_delay=0 gmin=16 r_factor=94 mos_lq=45 mos_cq=45 jb_nominal_delay=0 jb_maximum_delay=0 jb_absolute_delay=0
2012/05/31 13:01:18.180 Media Patch:0xd740b700 RTP Session 1, transmit statistics: packets=1401 octets=224160 avgTime=20 maxTime=21 minTime=19
2012/05/31 13:01:19.516 Media Patch:0xd744c700 RTP Session 1, OnRxSenderReport: ssrc=2073800661 ntp=2012/5/31-13:1:23.898228 rtp=240000 psent=1500 osent=240000
RR: ssrc=1197576518 fraction=0 lost=0 last_seq=16014 jitter=1 lsr=894:26:39.687 dlsr=2:38:54.767
2012/05/31 13:01:19.516 Media Patch:0xd744c700 RTP Session 1, OnSourceDescription: 1 entries
ssrc=2073800661
item[0]: type=CNAME data=""
2012/05/31 13:01:20.180 Media Patch:0xd740b700 RTP Session 1, transmit statistics: packets=1501 octets=240160 avgTime=19 maxTime=21 minTime=19
2012/05/31 13:01:22.180 Media Patch:0xd740b700 RTP Session 1, transmit statistics: packets=1601 octets=256160 avgTime=20 maxTime=21 minTime=19
2012/05/31 13:01:24.179 Media Patch:0xd740b700 RTP Session 1, transmit statistics: packets=1701 octets=272160 avgTime=20 maxTime=21 minTime=19
2012/05/31 13:01:24.517 Media Patch:0xd744c700 RTP Session 1, OnRxSenderReport: ssrc=2073800661 ntp=2012/5/31-13:1:28.899293 rtp=280160 psent=1751 osent=280160
RR: ssrc=1197576518 fraction=0 lost=0 last_seq=16264 jitter=1 lsr=894:26:39.687 dlsr=8:36:53.928
2012/05/31 13:01:24.517 Media Patch:0xd744c700 RTP Session 1, OnSourceDescription: 1 entries
ssrc=2073800661
item[0]: type=CNAME data=""
2012/05/31 13:01:26.180 Media Patch:0xd740b700 RTP Session 1, transmit statistics: packets=1801 octets=288160 avgTime=20 maxTime=21 minTime=19
2012/05/31 13:01:28.180 Media Patch:0xd740b700 RTP Session 1, transmit statistics: packets=1901 octets=304160 avgTime=20 maxTime=21 minTime=19
2012/05/31 13:01:29.517 Media Patch:0xd744c700 RTP Session 1, OnRxSenderReport: ssrc=2073800661 ntp=2012/5/31-13:1:33.899167 rtp=320160 psent=2001 osent=320160
RR: ssrc=1197576518 fraction=0 lost=0 last_seq=16514 jitter=1 lsr=894:26:39.687 dlsr=14:34:48.765
2012/05/31 13:01:29.517 Media Patch:0xd744c700 RTP Session 1, OnSourceDescription: 1 entries
ssrc=2073800661
item[0]: type=CNAME data=""
2012/05/31 13:01:30.032 Media Patch:0xd744c700 RTP Session 1, SentSenderReport: ssrc=1197576518 ntp=3547447290.139366064 rtp=0 psent=1993 osent=318880
2012/05/31 13:01:30.032 Media Patch:0xd744c700 RTP Session 1, SentReceiverReport: ssrc=2073800661 fraction=0 lost=0 last_seq=1510 jitter=1748234 lsr=3221087778 dlsr=33751
2012/05/31 13:01:30.032 Media Patch:0xd744c700 RTP Session 1, sending SDES: root@Fax-SRV
2012/05/31 13:01:30.032 Media Patch:0xd744c700 RTP Session 1, SentExtendedReport: ssrc=1197576518 loss_rate=0 discard_rate=0 burst_density=128 gap_density=0 burst_duration=40597 gap_duration=7 round_trip_delay=1 end_system_delay=0 gmin=16 r_factor=94 mos_lq=45 mos_cq=45 jb_nominal_delay=0 jb_maximum_delay=0 jb_absolute_delay=0
2012/05/31 13:01:30.180 Media Patch:0xd740b700 RTP Session 1, transmit statistics: packets=2001 octets=320160 avgTime=19 maxTime=21 minTime=19
2012/05/31 13:01:32.180 Media Patch:0xd740b700 RTP Session 1, transmit statistics: packets=2101 octets=336160 avgTime=20 maxTime=21 minTime=19
2012/05/31 13:01:34.180 Media Patch:0xd740b700 RTP Session 1, transmit statistics: packets=2201 octets=352160 avgTime=20 maxTime=21 minTime=19
2012/05/31 13:01:34.518 Media Patch:0xd744c700 RTP Session 1, OnRxSenderReport: ssrc=2073800661 ntp=2012/5/31-13:1:38.899210 rtp=360160 psent=2251 osent=360160
RR: ssrc=1197576518 fraction=0 lost=0 last_seq=16764 jitter=1 lsr=894:40:34.382 dlsr=5:20:58.605
2012/05/31 13:01:34.518 Media Patch:0xd744c700 RTP Session 1, OnSourceDescription: 1 entries
ssrc=2073800661
item[0]: type=CNAME data=""
2012/05/31 13:01:36.180 Media Patch:0xd740b700 RTP Session 1, transmit statistics: packets=2301 octets=368160 avgTime=20 maxTime=21 minTime=19
2012/05/31 13:01:38.179 Media Patch:0xd740b700 RTP Session 1, transmit statistics: packets=2401 octets=384160 avgTime=19 maxTime=21 minTime=19
2012/05/31 13:01:39.517 Media Patch:0xd744c700 RTP Session 1, OnRxSenderReport: ssrc=2073800661 ntp=2012/5/31-13:1:43.899171 rtp=400160 psent=2501 osent=400160
RR: ssrc=1197576518 fraction=0 lost=0 last_seq=17014 jitter=1 lsr=894:40:34.382 dlsr=11:18:53.442
2012/05/31 13:01:39.517 Media Patch:0xd744c700 RTP Session 1, OnSourceDescription: 1 entries
ssrc=2073800661
item[0]: type=CNAME data=""
2012/05/31 13:01:40.180 Media Patch:0xd740b700 RTP Session 1, transmit statistics: packets=2501 octets=400160 avgTime=20 maxTime=21 minTime=19
2012/05/31 13:01:40.500 Media Patch:0xd740b700 RTP Session 1, SentSenderReport: ssrc=1197576518 ntp=3547447300.2147687040 rtp=0 psent=2517 osent=402720
2012/05/31 13:01:40.500 Media Patch:0xd740b700 RTP Session 1, SentReceiverReport: ssrc=2073800661 fraction=0 lost=0 last_seq=2147 jitter=0 lsr=3221743138 dlsr=64421
2012/05/31 13:01:40.500 Media Patch:0xd740b700 RTP Session 1, sending SDES: root@Fax-SRV
2012/05/31 13:01:40.500 Media Patch:0xd740b700 RTP Session 1, SentExtendedReport: ssrc=1197576518 loss_rate=0 discard_rate=0 burst_density=128 gap_density=0 burst_duration=51076 gap_duration=1 round_trip_delay=1 end_system_delay=0 gmin=16 r_factor=94 mos_lq=45 mos_cq=45 jb_nominal_delay=0 jb_maximum_delay=0 jb_absolute_delay=0
2012/05/31 13:01:42.180 Media Patch:0xd740b700 RTP Session 1, transmit statistics: packets=2601 octets=416160 avgTime=20 maxTime=21 minTime=19
2012/05/31 13:01:44.180 Media Patch:0xd740b700 RTP Session 1, transmit statistics: packets=2701 octets=432160 avgTime=19 maxTime=21 minTime=19
2012/05/31 13:01:44.517 Media Patch:0xd744c700 RTP Session 1, OnRxSenderReport: ssrc=2073800661 ntp=2012/5/31-13:1:48.899198 rtp=440160 psent=2751 osent=440160
RR: ssrc=1197576518 fraction=0 lost=0 last_seq=17264 jitter=1 lsr=894:52:00.387 dlsr=4:47:28.550
2012/05/31 13:01:44.517 Media Patch:0xd744c700 RTP Session 1, OnSourceDescription: 1 entries
ssrc=2073800661
item[0]: type=CNAME data=""
2012/05/31 13:01:46.180 Media Patch:0xd740b700 RTP Session 1, transmit statistics: packets=2801 octets=448160 avgTime=20 maxTime=21 minTime=19
2012/05/31 13:01:46.434 Opal Liste…0xeeaf5700 OpalUDP Binding to interface: 192.168.22.198:6069
2012/05/31 13:01:46.435 Opal Liste…0xeeaf5700 SIP PDU OPTIONS sip:192.168.22.198 received: rem=udp$192.168.22.200:5060,local=udp$192.168.22.198:6069,if=192.168.22.198%eth0
2012/05/31 13:01:46.436 Opal Liste…0xeeaf5700 SIP Sending PDU 200 OK (364 bytes) to: rem=udp$192.168.22.200:5060,local=udp$192.168.22.198:6069,if=192.168.22.198%eth0
2012/05/31 13:01:46.436 Opal Liste…0xeeaf5700 OpalUDP Setting interface to 192.168.22.198%eth0
2012/05/31 13:01:46.436 Opal Liste…0xeeaf5700 Opal Transport clean up on termination
2012/05/31 13:01:48.180 Media Patch:0xd740b700 RTP Session 1, transmit statistics: packets=2901 octets=464160 avgTime=20 maxTime=21 minTime=19
2012/05/31 13:01:49.246 Media Patch:0xd744c700 RTP Session 1, SentSenderReport: ssrc=1197576518 ntp=3547447309.1056740518 rtp=0 psent=2954 osent=472640
2012/05/31 13:01:49.246 Media Patch:0xd744c700 RTP Session 1, SentReceiverReport: ssrc=2073800661 fraction=0 lost=0 last_seq=2671 jitter=0 lsr=3222070820 dlsr=309919
2012/05/31 13:01:49.246 Media Patch:0xd744c700 RTP Session 1, sending SDES: root@Fax-SRV
2012/05/31 13:01:49.246 Media Patch:0xd744c700 RTP Session 1, SentExtendedReport: ssrc=1197576518 loss_rate=0 discard_rate=0 burst_density=128 gap_density=0 burst_duration=59816 gap_duration=4 round_trip_delay=1 end_system_delay=0 gmin=16 r_factor=94 mos_lq=45 mos_cq=45 jb_nominal_delay=0 jb_maximum_delay=0 jb_absolute_delay=0
2012/05/31 13:01:49.407 Housekeeper:0xeeb36700 ModemEngineBody::OnTimerCallback stConnectWait Timeout 0
2012/05/31 13:01:49.407 9979(e):40…0xeeab4700 9979 AudioEngine Detach
2012/05/31 13:01:49.407 9979(e):40…0xeeab4700 9979 AudioEngine OnChangeModemClass to mcUndefined
2012/05/31 13:01:49.407 9979(e):40…0xeeab4700 9979 AudioEngine OnDetach Detached
2012/05/31 13:01:49.407 9979(e):40…0xeeab4700 9979 AudioEngine OnResetModemState
2012/05/31 13:01:49.407 9979(e):40…0xeeab4700 ModemEngineBody::_DetachEngine Detached mceAudio
2012/05/31 13:01:49.407 9979(e):40…0xeeab4700 ModemEndPoint::OnMyCallback command=clearcall extra=1
2012/05/31 13:01:49.408 9979(e):40…0xeeab4700 OpalCon Call end reason for Call[C7d7890f51]-EP[modem:/C7d7890f51/0] set to EndedByLocalUser
2012/05/31 13:01:49.408 9979(e):40…0xeeab4700 Call Clearing Call[C7d7890f51] reason=EndedByLocalUser
2012/05/31 13:01:49.408 9979(e):40…0xeeab4700 OpalCon SetPhase from AlertingPhase to ReleasingPhase for Call[C7d7890f51]-EP[modem:/C7d7890f51/0]
2012/05/31 13:01:49.408 9979(e):40…0xeeab4700 OpalCon Releasing Call[C7d7890f51]-EP[modem:/C7d7890f51/0]
2012/05/31 13:01:49.408 9979(e):40…0xeeab4700 ModemConnection::OnReleased Call[C7d7890f51]-EP[modem:/C7d7890f51/0]
2012/05/31 13:01:49.408 9979(e):40…0xeeab4700 AudioModemMediaStream::Close AudioModemMediaStream-Sink-PCM-16
2012/05/31 13:01:49.408 9979(e):40…0xeeab4700 9979 AudioEngine CloseIn: close 0x7fd8ac00d200
2012/05/31 13:01:49.408 9979(e):40…0xeeab4700 OpalCon No filter to remove for stage PCM-16
2012/05/31 13:01:49.408 9979(e):40…0xeeab4700 OpalCon No filter to remove for stage YUV420P
2012/05/31 13:01:49.408 9979(e):40…0xeeab4700 OpalCon No filter to remove for stage PCM-16
2012/05/31 13:01:49.408 9979(e):40…0xeeab4700 Patch Removing media stream sink AudioModemMediaStream-Sink-PCM-16
2012/05/31 13:01:49.409 9979(e):40…0xeeab4700 Media Closing RTP for OpalRTPMediaStream-Source-G.711-uLaw-64k
2012/05/31 13:01:49.409 9979(e):40…0xeeab4700 RTP_UDP Session 1, Shutting down read.
2012/05/31 13:01:49.409 9979(e):40…0xeeab4700 OpalCon No filter to remove for stage PCM-16
2012/05/31 13:01:49.409 Media Patch:0xd744c700 RTP_UDP Session 1, Read shutdown.
2012/05/31 13:01:49.409 9979(e):40…0xeeab4700 OpalCon No filter to remove for stage YUV420P
2012/05/31 13:01:49.409 9979(e):40…0xeeab4700 OpalCon No filter to remove for stage PCM-16
2012/05/31 13:01:49.409 9979(e):40…0xeeab4700 OpalCon No filter to remove for stage G.711-uLaw-64k
2012/05/31 13:01:49.409 Media Patch:0xd744c700 PTLib Thread ended: name=“Media Patch:0xd744c700”, real=59.232, kernel=0.000 (0%), user=0.280 (0.4%), both=0.280 (0.4%)
2012/05/31 13:01:49.409 9979(e):40…0xeeab4700 Patch Closing media patch Patch[0x7fd8ac00d570] OpalRTPMediaStream-Source-G.711-uLaw-64k
2012/05/31 13:01:49.409 9979(e):40…0xeeab4700 OpalCon Removed media stream OpalRTPMediaStream-Source-G.711-uLaw-64k
2012/05/31 13:01:49.409 9979(e):40…0xeeab4700 OpalCon Removed media stream AudioModemMediaStream-Sink-PCM-16
2012/05/31 13:01:49.410 9979(e):40…0xeeab4700 AudioModemMediaStream::Close AudioModemMediaStream-Source-PCM-16
2012/05/31 13:01:49.410 9979(e):40…0xeeab4700 9979 AudioEngine CloseOut: close 0x7fd8ac010a50
2012/05/31 13:01:49.410 9979(e):40…0xeeab4700 OpalCon No filter to remove for stage PCM-16
2012/05/31 13:01:49.410 9979(e):40…0xeeab4700 OpalCon No filter to remove for stage YUV420P
2012/05/31 13:01:49.410 9979(e):40…0xeeab4700 OpalCon No filter to remove for stage PCM-16
2012/05/31 13:01:49.410 9979(e):40…0xeeab4700 OpalCon No filter to remove for stage PCM-16
2012/05/31 13:01:49.410 9979(e):40…0xeeab4700 Patch Closing media patch Patch[0x7fd8ac011140] AudioModemMediaStream-Source-PCM-16 -> OpalRTPMediaStream-Sink-G.711-uLaw-64k
2012/05/31 13:01:49.410 9979(e):40…0xeeab4700 Media Closing RTP for OpalRTPMediaStream-Sink-G.711-uLaw-64k
2012/05/31 13:01:49.410 9979(e):40…0xeeab4700 RTP_UDP Session 1, shutting down write.
2012/05/31 13:01:49.411 9979(e):40…0xeeab4700 OpalCon No filter to remove for stage PCM-16
2012/05/31 13:01:49.411 9979(e):40…0xeeab4700 OpalCon No filter to remove for stage YUV420P
2012/05/31 13:01:49.411 9979(e):40…0xeeab4700 OpalCon No filter to remove for stage PCM-16
2012/05/31 13:01:49.411 9979(e):40…0xeeab4700 OpalCon No filter to remove for stage G.711-uLaw-64k
2012/05/31 13:01:49.411 9979(e):40…0xeeab4700 Patch Removing media stream sink OpalRTPMediaStream-Sink-G.711-uLaw-64k
2012/05/31 13:01:49.411 9979(e):40…0xeeab4700 OpalCon Removed media stream OpalRTPMediaStream-Sink-G.711-uLaw-64k
2012/05/31 13:01:49.420 Media Patch:0xd740b700 PTLib Thread ended: name=“Media Patch:0xd740b700”, real=59.239, kernel=0.000 (0%), user=0.240 (0.4%), both=0.240 (0.4%)
2012/05/31 13:01:49.421 9979(e):40…0xeeab4700 OpalCon Removed media stream AudioModemMediaStream-Source-PCM-16
2012/05/31 13:01:49.421 9979(e):40…0xeeab4700 OpalCon Media streams closed.
2012/05/31 13:01:49.422 9979(e):40…0xeeab4700 OpalMan OnReleased Call[C7d7890f51]-EP[modem:/C7d7890f51/0]
2012/05/31 13:01:49.422 9979(e):40…0xeeab4700 Call OnReleased Call[C7d7890f51]-EP[modem:/C7d7890f51/0]
2012/05/31 13:01:49.422 9979(e):40…0xeeab4700 OpalCon SetPhase from AlertingPhase to ReleasingPhase for Call[C7d7890f51]-EP[c235ea2a-75a9-e111-8ae0-005056800015]
2012/05/31 13:01:49.422 9979(e):40…0xeeab4700 OpalCon Releasing asynchronously Call[C7d7890f51]-EP[c235ea2a-75a9-e111-8ae0-005056800015]
2012/05/31 13:01:49.422 9979(e):40…0xeeab4700 OpalCon SetPhase from ReleasingPhase to ReleasedPhase for Call[C7d7890f51]-EP[modem:/C7d7890f51/0]
2012/05/31 13:01:49.422 9979(e):40…0xeeab4700 OpalCon Connection Call[C7d7890f51]-EP[modem:/C7d7890f51/0] released
Initial Time: Thu, 31 May 2012 13:00:49 +03:00
SetUpPhase: 0.000
ProceedingPhase: N/A
AlertingPhase: 0.764
ConnectedPhase: N/A
EstablishedPhase: N/A
ForwardingPhase: N/A
ReleasingPhase: 1:00.000
ReleasedPhase: 1:00.014
Call end reason: EndedByLocalUser
2012/05/31 13:01:49.422 OnRelease:0xd740b700 OpalCon Call end reason for Call[C7d7890f51]-EP[c235ea2a-75a9-e111-8ae0-005056800015] set to EndedByLocalUser
2012/05/31 13:01:49.422 OnRelease:0xd740b700 SIP OnReleased: Call[C7d7890f51]-EP[c235ea2a-75a9-e111-8ae0-005056800015]
2012/05/31 13:01:49.422 OnRelease:0xd740b700 SIP Cancelling 1 transactions.
2012/05/31 13:01:49.422 9979(e):40…0xeeab4700 ModemEndPoint::OnMyCallback request={
calltoken=modem:/C7d7890f51/0
command=clearcall
response=confirm
modemtoken=9979
}
2012/05/31 13:01:49.422 9979(e):40…0xeeab4700 <-- {
0d 0a 4e 4f 20 43 41 52 52 49 45 52 0d 0a …NO CARRIER… }
2012/05/31 13:01:49.423 OnRelease:0xd740b700 SIP Sending PDU CANCEL sip:025871906@192.168.22.201 (367 bytes) to: rem=udp$192.168.22.201:5060,local=udp$192.168.22.198:6069,if=192.168.22.198%eth0
2012/05/31 13:01:49.423 OnRelease:0xd740b700 OpalUDP Setting interface to 192.168.22.198%eth0
2012/05/31 13:01:49.423 OnRelease:0xd740b700 SIP Set state Terminated_Aborted for INVITE transaction id=z9hG4bK9c2b602b-75a9-e111-8ae0-005056800015
2012/05/31 13:01:49.423 OnRelease:0xd740b700 SIP Transaction 2 INVITE sip:025871906@192.168.22.201 failed, unknown handler, ID: 2a4bea2a-75a9-e111-8ae0-005056800015@Fax-SRV
2012/05/31 13:01:49.423 Opal Liste…0xeeaf5700 OpalUDP Binding to interface: 192.168.22.198:6069
2012/05/31 13:01:49.423 OnRelease:0xd740b700 OpalCon Media streams closed.
2012/05/31 13:01:49.423 OnRelease:0xd740b700 OpalMan OnReleased Call[C7d7890f51]-EP[c235ea2a-75a9-e111-8ae0-005056800015]
2012/05/31 13:01:49.423 OnRelease:0xd740b700 Call OnReleased Call[C7d7890f51]-EP[c235ea2a-75a9-e111-8ae0-005056800015]
2012/05/31 13:01:49.424 OnRelease:0xd740b700 Call[C7d7890f51] cleared (EndedByLocalUser)
2012/05/31 13:01:49.424 OnRelease:0xd740b700 OpalMan OnClearedCall Call[C7d7890f51] from “modem:” to "sip:025871906@192.168.22.201"
2012/05/31 13:01:49.424 Opal Liste…0xeeaf5700 SIP PDU 487 Request Terminated received: rem=udp$192.168.22.201:5060,local=udp$192.168.22.198:6069,if=192.168.22.198%eth0
2012/05/31 13:01:49.424 OnRelease:0xd740b700 OpalCon SetPhase from ReleasingPhase to ReleasedPhase for Call[C7d7890f51]-EP[c235ea2a-75a9-e111-8ae0-005056800015]
2012/05/31 13:01:49.424 OnRelease:0xd740b700 OpalCon Connection Call[C7d7890f51]-EP[c235ea2a-75a9-e111-8ae0-005056800015] released
Initial Time: Thu, 31 May 2012 13:00:49 +03:00
SetUpPhase: 0.014
ProceedingPhase: 0.018
AlertingPhase: 0.763
ConnectedPhase: N/A
EstablishedPhase: N/A
ForwardingPhase: N/A
ReleasingPhase: 1:00.013
ReleasedPhase: 1:00.015
Call end reason: EndedByLocalUser
2012/05/31 13:01:49.424 OnRelease:0xd740b700 RTP Closing session 1
2012/05/31 13:01:49.424 OnRelease:0xd740b700 RTP Closing session 1
2012/05/31 13:01:49.424 Pool:0xd744c700 SIP Handling PDU “1 INVITE <487>” for transaction=z9hG4bK0ecaeb2a-75a9-e111-8ae0-005056800015
2012/05/31 13:01:49.424 Pool:0xd744c700 SIP Sending PDU ACK sip:025871906@192.168.22.201 (376 bytes) to: rem=udp$192.168.22.201:5060,local=udp$192.168.22.198:6069,if=192.168.22.198%eth0
2012/05/31 13:01:49.425 Pool:0xd744c700 OpalUDP Setting interface to 192.168.22.198%eth0
2012/05/31 13:01:49.425 Opal Liste…0xeeaf5700 Opal Transport clean up on termination
2012/05/31 13:01:49.425 OnRelease:0xd740b700 RTP Session 1, SentSenderReport: ssrc=1197576518 ntp=3547447309.1822060138 rtp=0 psent=2962 osent=473920
2012/05/31 13:01:49.425 Opal Liste…0xeeaf5700 OpalUDP Binding to interface: 192.168.22.198:6069
2012/05/31 13:01:49.425 OnRelease:0xd740b700 PTLib Thread ended: name=“OnRelease:0xd740b700”, real=0.002, kernel=0.000 (0%), user=0.000 (0%), both=0.000 (0%)
2012/05/31 13:01:49.425 Opal Liste…0xeeaf5700 SIP PDU 200 OK received: rem=udp$192.168.22.201:5060,local=udp$192.168.22.198:6069,if=192.168.22.198%eth0
2012/05/31 13:01:49.425 Opal Liste…0xeeaf5700 Opal Transport clean up on termination
2012/05/31 13:01:49.425 Pool:0xd744c700 SIP Handling PDU “1 CANCEL <200>” for transaction=z9hG4bK0ecaeb2a-75a9-e111-8ae0-005056800015
2012/05/31 13:01:50.098 Opal Garbage:0xeebf9700 9979 AudioEngine ~AudioEngine
2012/05/31 13:01:50.098 Opal Garbage:0xeebf9700 PseudoModemQ::Enqueue 9979
2012/05/31 13:01:50.098 Opal Garbage:0xeebf9700 ModemEngineBody::Request: stCommand request={
calltoken=modem:/C7d7890f51/0
command=clearcall
}
2012/05/31 13:01:50.098 Opal Garbage:0xeebf9700 ModemEngineBody::Request: call already in cstCleared state
2012/05/31 13:01:50.098 Opal Garbage:0xeebf9700 OpalCon Connection Call[C7d7890f51]-EP[modem:/C7d7890f51/0] destroyed.
2012/05/31 13:01:50.423 9979(e):40…0xeeab4700 --> ATH0
2012/05/31 13:01:50.423 9979(e):40…0xeeab4700 <-- {
0d 0a 4f 4b 0d 0a …OK… }
2012/05/31 13:01:50.423 9979(i):36…0xdc09f700 --> read ERROR -1 Input/output error
2012/05/31 13:01:50.424 9979(i):36…0xdc09f700 --> Stopped
2012/05/31 13:01:50.424 9979(i):36…0xdc09f700 PTLib Thread ended: name=“9979(i):3691640576:0xdc09f700”, real=70.278, kernel=0.000 (0%), user=0.000 (0%), both=0.000 (0%)
2012/05/31 13:01:50.434 9979(o):36…0xdc0e0700 <-- Stopped
2012/05/31 13:01:50.434 9979(o):36…0xdc0e0700 PTLib Thread ended: name=“9979(o):3691906816:0xdc0e0700”, real=70.288, kernel=0.000 (0%), user=0.000 (0%), both=0.000 (0%)
2012/05/31 13:01:50.444 9979(e):40…0xeeab4700 <-> Stopped
2012/05/31 13:01:50.444 9979(e):40…0xeeab4700 PTLib Thread ended: name=“9979(e):4004202240:0xeeab4700”, real=70.299, kernel=0.000 (0%), user=0.020 (0%), both=0.020 (0%)
2012/05/31 13:01:50.454 9979(b):40…0xeebb8700 PseudoModemPty::OpenPty removed link /dev/9979 -> /dev/pts/7
2012/05/31 13:01:50.454 9979(b):40…0xeebb8700 PseudoModemPty::OpenPty read ERROR -1 Input/output error
2012/05/31 13:01:50.454 9979(b):40…0xeebb8700 PseudoModemPty::OpenPty added link /dev/9979 -> /dev/pts/7
2012/05/31 13:01:50.455 9979(e):40…0xeeab4700 RenameCurrentThread old ThreadName=ModemEngine:0xeeab4700
2012/05/31 13:01:50.455 9979(e):40…0xeeab4700 <-> Started
2012/05/31 13:01:50.455 9979(o):36…0xdc09f700 RenameCurrentThread old ThreadName=OutPty:0xdc09f700
2012/05/31 13:01:50.455 9979(o):36…0xdc09f700 <-- Started
2012/05/31 13:01:50.455 9979(i):36…0xdc0e0700 RenameCurrentThread old ThreadName=InPty:0xdc0e0700
2012/05/31 13:01:50.455 9979(i):36…0xdc0e0700 --> Started
2012/05/31 13:01:51.435 Housekeeper:0xeeb36700 SIP Set state Terminated_Success for SIP_PDU_Method<14> transaction id=z9hG4bK2519a904
2012/05/31 13:01:54.447 Housekeeper:0xeeb36700 SIP Set state Terminated_Cancelled for INVITE transaction id=z9hG4bK0ecaeb2a-75a9-e111-8ae0-005056800015
2012/05/31 13:01:54.447 Housekeeper:0xeeb36700 SIP Transaction 1 INVITE sip:025871906@192.168.22.201 failed, unknown handler, ID: 2a4bea2a-75a9-e111-8ae0-005056800015@Fax-SRV
2012/05/31 13:01:56.100 Opal Garbage:0xeebf9700 Opal Transport clean up on termination
2012/05/31 13:01:56.100 Opal Garbage:0xeebf9700 Opal Transport clean up on termination
2012/05/31 13:01:56.101 Opal Garbage:0xeebf9700 RTP Session 1, final statistics:
firstPacketSent = Thu, 31 May 2012 13:00:50 +03:00
packetsSent = 2962
octetsSent = 473920
bitRateSent = 58328
averageSendTime = 20
maximumSendTime = 21
minimumSendTime = 19
packetsLostByRemote= 0
jitterLevelOnRemote= 1
firstPacketReceived= Thu, 31 May 2012 13:00:50 +03:00
packetsReceived = 2961
octetsReceived = 473760
bitRateReceived = 58308
packetsLost = 0
packetsTooLate = 0
packetOverruns = 0
packetsOutOfOrder = 0
averageReceiveTime = 20
maximumReceiveTime = 21
minimumReceiveTime = 19
averageJitter = 0
maximumJitter = 33554431
2012/05/31 13:01:56.101 Opal Garbage:0xeebf9700 VoIP Metrics RTCP_XR_Metrics final statistics:
R Factor = 94
MOS = 4.42423
2012/05/31 13:01:56.101 Opal Garbage:0xeebf9700 OpalCon Connection Call[C7d7890f51]-EP[c235ea2a-75a9-e111-8ae0-005056800015] destroyed.
2012/05/31 13:01:57.102 Opal Garbage:0xeebf9700 Call Destroyed Call[C7d7890f51]