Can someone give me a general overview of how to read the log files from an Avaya IP Office system? It's running version 7.
I'm trying to understand a situation where some calls are apparently either not arriving on the Avaya, or not being delivered down the SIP trunk.
There may be multiple problems, but one that has been clearly identified is that if you ring the number having done a 141 to withhold your CLI then calls to the numbers routed to the SIP trunk will always fail (10-20 seconds silence and then the call is dropped). In these instances there is no SIP traffic at all, so the call is either not making it to the Avaya or it is getting lost there.
Looking at the logs, I can see where calls are made over the SIP lines but I cannot understand where all the incoming calls are (i.e. ideally i'm looking for a definitive way to say "this is a list of all the calls that arrived" - so that I can see if it's there, and if so follow it through). One problem is that with CLI not presented, it's somewhat tricky to find.
Taking one call as an example, in this case call 21187 (I presume that's the call ID).
569797641mS CMCallEvt: CREATE CALL:21187 (f45ad72c)
569797643mS CD2: CALL:S 5.15.1,0.67681.0,0,0,1,0,0,0,Line 5,,,2.3,0.0,100.0,612345,0.0,01234123123,,,100,,100,,0,16,0,1,16.0,,,,,,,0,2,0,0,0,0,,,0,,0,0,0,0,,21187,0,0,,0,,3,0,0,0,0,0,0,1,618,1,,,,,,,,,,,,,,,
569797643mS CMCallEvt: 5.15.1 21187 Q931 Trunk:5 CHAN=2: StateChange: END=A CMCSIdle->CMCSDialInitiated
569797644mS CMTARGET: 5.15.1 21187 Q931 Trunk:5 CHAN=2: LOOKUP CALL ROUTE: type=0 called_party=612345 sub= calling=01234123123 dir=in complete=1 ses=0
569797644mS CMTARGET: 5.15.1 21187 Q931 Trunk:5 CHAN=2: SET BESTMATCH: length 0 vs -1 match= dest=8000
569797644mS CMTARGET: 5.15.1 21187 Q931 Trunk:5 CHAN=2: SET BESTMATCH: length 6 vs 0 match=612345 dest=8000
569797645mS CMCallEvt: Priority hike: call 21187 priority 0->1
569797645mS CMTARGET: 5.15.1 21187 Q931 Trunk:5 CHAN=2: LOOKUP ICR: DDI= CGPN=01234123123 (Destination 8000 ) => CDPN=8000
569797645mS CMTARGET: 5.15.1 21187 Q931 Trunk:5 CHAN=2: ADD TARGET (N): number=8000 type=0 depth=1 nobar=1 setorig=1 ses=0
569797646mS CMTARGET: 5.15.1 21187 Q931 Trunk:5 CHAN=2: SYS SC: 8000 4 sc=type=Dial64K code=8000, num=8000"@123.12.123.12" callinfop->sending_complete=1 secondary_dialtone=
569797650mS CMTARGET: DIAL LINE: 21187 GROUP = 40 SUCCESS = f462b458
569797650mS CMTARGET: 5.15.1 21187 Q931 Trunk:5 CHAN=2: INITIAL TARGETING SUCCEEDED
569797651mS CMTARGET: 5.15.1 21187 Q931 Trunk:5 CHAN=2: GetNoAnswerTimer:15
569797651mS CMCallEvt: 5.15.1 21187 Q931 Trunk:5 CHAN=2: StateChange: END=A CMCSDialInitiated->CMCSDialled
569797652mS CMCallEvt: 0.67681.0 21187 TargetingEP: StateChange: END=B CMCSIdle->CMCSOffering
569797653mS CMCallEvt: 17.67682.0 21187 SIPTrunk Endpoint: StateChange: END=T CMCSIdle->CMCSOffering
569797655mS Sip: 17.67682.0 21187 SIPTrunk Endpoint(f462b458) received CMSetup
569797656mS Sip: 17.67682.0 21187 SIPTrunk Endpoint(f462a2f4) SetLocalRTPAddress to 123.12.123.13:49220 (index 0)
569797659mS CD2: CALL:S 5.15.1,0.67681.0,8,0,1,0,0,0,Line 5,,Line 17,2.3,0.0,100.0,8000,0.0,01234123123,,,0,612345,100,,0,16,0,1,16.0,,,,,,,0,18,0,0,0,0,eng,,0,,0,0,0,0,,21187,0,0,,0,,3,0,0,0,0,0,0,1,618,1,,,,,,,,,,,,,,,
569797687mS Sip: 17.67682.0 21187 SIPTrunk Endpoint(f462a2f4) SetRemoteRTPAddress to 123.12.123.12:49242 (index 0)
569797688mS CMCallEvt: 0.67681.0 21187 TargetingEP: RequestEnd 17.67682.0 21187 SIPTrunk Endpoint
569797688mS CMTARGET: 5.15.1 21187 Q931 Trunk:5 CHAN=2: CancelTimer CMTCNoAnswerTimeout
569797689mS CMCallEvt: 17.67682.0 21187 SIPTrunk Endpoint: StateChange: END=B CMCSOffering->CMCSRinging
569797690mS CMCallEvt: 5.15.1 21187 Q931 Trunk:5 CHAN=2: StateChange: END=A CMCSDialled->CMCSRingBack
569797699mS CD2: CALL:S 5.15.1,0.67681.0,1,1,1,0,1,0,Line 5,Line 17,,2.3,0.0,100.100,8000@123.12.123.12,0.0,01234123123,,,0,612345,100,,0,16,0,1,8.0,,,,,,,0,58,0,10,0,0,eng,,0,,0,0,0,0,,21187,0,0,,0,,3,0,0,0,0,0,0,1,618,1,,,,,,,,,,,,,,,
569797993mS CMCallEvt: 17.67682.0 21187 SIPTrunk Endpoint: StateChange: END=B CMCSRinging->CMCSConnReq
569797993mS CMCallEvt: 5.15.1 21187 Q931 Trunk:5 CHAN=2: StateChange: END=A CMCSRingBack->CMCSOGConnReq
569798003mS CD2: CALL:S 5.15.1,0.67681.0,2,2,1,0,1,0,Line 5,Line 17,,2.3,0.0,100.100,8000@123.12.123.12,0.0,01234123123,,,0,612345,100,,0,16,0,1,8.0,,,,,,,0,362,0,0,0,304,eng,,0,,0,0,0,0,,21187,0,0,,0,,3,0,0,0,0,0,0,1,618,1,,,,,,,,,,,,,,,
569798014mS CMCallEvt: 5.15.1 21187 Q931 Trunk:5 CHAN=2: StateChange: END=A CMCSOGConnReq->CMCSConnected
569798015mS CMTARGET: 5.15.1 21187 Q931 Trunk:5 CHAN=2: ~CMTargetHandler f4a3447c ep f44b3b00
569798016mS CMCallEvt: 17.67682.0 21187 SIPTrunk Endpoint: StateChange: END=B CMCSConnReq->CMCSConnected
569798017mS Sip: 17.67682.0 21187 SIPTrunk Endpoint(f462b458) received CMConnectAck
570414342mS CMCallEvt: 17.67682.0 21187 SIPTrunk Endpoint: StateChange: END=B CMCSConnected->CMCSCompleted
570414346mS CD2: CALL:S 5.15.1,0.67681.0,2,3,1,0,0,0,Line 5,Line 17,,2.3,0.0,100.100,8000@123.12.123.12,0.0,01234123123,,,0,612345,100,,0,16,0,1,8.0,,,,,,,0,616704,0,0,616326,304,eng,,0,,0,0,0,0,,21187,0,0,,0,,3,0,0,0,0,0,0,1,618,1,,,,,,,,,,,,,,,
570414348mS CMCallEvt: END CALL:21187 (f45ad72c)
The above is somewhat sanitised to remove specific numbers etc.
The incoming DDI presented to us is: 612345
The CLI of the call shown is 01234123123
The SIP Switch IP address is 123.12.123.12
The call path as I understand it is, incoming call from network (Q931 channel) presented to 612345 is routed across SIP trunk to DDI of 8000 on the peer SIP system. Under most circumstances this works wonderfully. In some cases, including ones where the CLI is withheld, it doesn't.
If the CLI is withheld and the call is routed in to the Avaya to route directly to another service not going via the SIP trunk then this problem does not occur, so it seems related to the SIP configuration.
For my understanding though, what is happening in the above logs? It seems backwards from what i'd expect? I.e. i'm seeing a "Dial initiated" at the start, and an "Offering" in the middle?
Here's a breakdown of the state changes in the above extract:
569797643mS CMCallEvt: 5.15.1 21187 Q931 Trunk:5 CHAN=2: StateChange: END=A CMCSIdle->CMCSDialInitiated
569797651mS CMCallEvt: 5.15.1 21187 Q931 Trunk:5 CHAN=2: StateChange: END=A CMCSDialInitiated->CMCSDialled
569797652mS CMCallEvt: 0.67681.0 21187 TargetingEP: StateChange: END=B CMCSIdle->CMCSOffering
569797653mS CMCallEvt: 17.67682.0 21187 SIPTrunk Endpoint: StateChange: END=T CMCSIdle->CMCSOffering
569797689mS CMCallEvt: 17.67682.0 21187 SIPTrunk Endpoint: StateChange: END=B CMCSOffering->CMCSRinging
569797690mS CMCallEvt: 5.15.1 21187 Q931 Trunk:5 CHAN=2: StateChange: END=A CMCSDialled->CMCSRingBack
569797993mS CMCallEvt: 17.67682.0 21187 SIPTrunk Endpoint: StateChange: END=B CMCSRinging->CMCSConnReq
569797993mS CMCallEvt: 5.15.1 21187 Q931 Trunk:5 CHAN=2: StateChange: END=A CMCSRingBack->CMCSOGConnReq
569798014mS CMCallEvt: 5.15.1 21187 Q931 Trunk:5 CHAN=2: StateChange: END=A CMCSOGConnReq->CMCSConnected
569798016mS CMCallEvt: 17.67682.0 21187 SIPTrunk Endpoint: StateChange: END=B CMCSConnReq->CMCSConnected
570414342mS CMCallEvt: 17.67682.0 21187 SIPTrunk Endpoint: StateChange: END=B CMCSConnected->CMCSCompleted
Is this only reporting the leg of the call once the decision has been made? Would there be earlier logs related to the original arrival of the call to the system?
Are there specific logging entries that must be enabled to see things more clearly?
Any help appreciated!
Kind Regards
Matt Peddlesden
I'm trying to understand a situation where some calls are apparently either not arriving on the Avaya, or not being delivered down the SIP trunk.
There may be multiple problems, but one that has been clearly identified is that if you ring the number having done a 141 to withhold your CLI then calls to the numbers routed to the SIP trunk will always fail (10-20 seconds silence and then the call is dropped). In these instances there is no SIP traffic at all, so the call is either not making it to the Avaya or it is getting lost there.
Looking at the logs, I can see where calls are made over the SIP lines but I cannot understand where all the incoming calls are (i.e. ideally i'm looking for a definitive way to say "this is a list of all the calls that arrived" - so that I can see if it's there, and if so follow it through). One problem is that with CLI not presented, it's somewhat tricky to find.
Taking one call as an example, in this case call 21187 (I presume that's the call ID).
569797641mS CMCallEvt: CREATE CALL:21187 (f45ad72c)
569797643mS CD2: CALL:S 5.15.1,0.67681.0,0,0,1,0,0,0,Line 5,,,2.3,0.0,100.0,612345,0.0,01234123123,,,100,,100,,0,16,0,1,16.0,,,,,,,0,2,0,0,0,0,,,0,,0,0,0,0,,21187,0,0,,0,,3,0,0,0,0,0,0,1,618,1,,,,,,,,,,,,,,,
569797643mS CMCallEvt: 5.15.1 21187 Q931 Trunk:5 CHAN=2: StateChange: END=A CMCSIdle->CMCSDialInitiated
569797644mS CMTARGET: 5.15.1 21187 Q931 Trunk:5 CHAN=2: LOOKUP CALL ROUTE: type=0 called_party=612345 sub= calling=01234123123 dir=in complete=1 ses=0
569797644mS CMTARGET: 5.15.1 21187 Q931 Trunk:5 CHAN=2: SET BESTMATCH: length 0 vs -1 match= dest=8000
569797644mS CMTARGET: 5.15.1 21187 Q931 Trunk:5 CHAN=2: SET BESTMATCH: length 6 vs 0 match=612345 dest=8000
569797645mS CMCallEvt: Priority hike: call 21187 priority 0->1
569797645mS CMTARGET: 5.15.1 21187 Q931 Trunk:5 CHAN=2: LOOKUP ICR: DDI= CGPN=01234123123 (Destination 8000 ) => CDPN=8000
569797645mS CMTARGET: 5.15.1 21187 Q931 Trunk:5 CHAN=2: ADD TARGET (N): number=8000 type=0 depth=1 nobar=1 setorig=1 ses=0
569797646mS CMTARGET: 5.15.1 21187 Q931 Trunk:5 CHAN=2: SYS SC: 8000 4 sc=type=Dial64K code=8000, num=8000"@123.12.123.12" callinfop->sending_complete=1 secondary_dialtone=
569797650mS CMTARGET: DIAL LINE: 21187 GROUP = 40 SUCCESS = f462b458
569797650mS CMTARGET: 5.15.1 21187 Q931 Trunk:5 CHAN=2: INITIAL TARGETING SUCCEEDED
569797651mS CMTARGET: 5.15.1 21187 Q931 Trunk:5 CHAN=2: GetNoAnswerTimer:15
569797651mS CMCallEvt: 5.15.1 21187 Q931 Trunk:5 CHAN=2: StateChange: END=A CMCSDialInitiated->CMCSDialled
569797652mS CMCallEvt: 0.67681.0 21187 TargetingEP: StateChange: END=B CMCSIdle->CMCSOffering
569797653mS CMCallEvt: 17.67682.0 21187 SIPTrunk Endpoint: StateChange: END=T CMCSIdle->CMCSOffering
569797655mS Sip: 17.67682.0 21187 SIPTrunk Endpoint(f462b458) received CMSetup
569797656mS Sip: 17.67682.0 21187 SIPTrunk Endpoint(f462a2f4) SetLocalRTPAddress to 123.12.123.13:49220 (index 0)
569797659mS CD2: CALL:S 5.15.1,0.67681.0,8,0,1,0,0,0,Line 5,,Line 17,2.3,0.0,100.0,8000,0.0,01234123123,,,0,612345,100,,0,16,0,1,16.0,,,,,,,0,18,0,0,0,0,eng,,0,,0,0,0,0,,21187,0,0,,0,,3,0,0,0,0,0,0,1,618,1,,,,,,,,,,,,,,,
569797687mS Sip: 17.67682.0 21187 SIPTrunk Endpoint(f462a2f4) SetRemoteRTPAddress to 123.12.123.12:49242 (index 0)
569797688mS CMCallEvt: 0.67681.0 21187 TargetingEP: RequestEnd 17.67682.0 21187 SIPTrunk Endpoint
569797688mS CMTARGET: 5.15.1 21187 Q931 Trunk:5 CHAN=2: CancelTimer CMTCNoAnswerTimeout
569797689mS CMCallEvt: 17.67682.0 21187 SIPTrunk Endpoint: StateChange: END=B CMCSOffering->CMCSRinging
569797690mS CMCallEvt: 5.15.1 21187 Q931 Trunk:5 CHAN=2: StateChange: END=A CMCSDialled->CMCSRingBack
569797699mS CD2: CALL:S 5.15.1,0.67681.0,1,1,1,0,1,0,Line 5,Line 17,,2.3,0.0,100.100,8000@123.12.123.12,0.0,01234123123,,,0,612345,100,,0,16,0,1,8.0,,,,,,,0,58,0,10,0,0,eng,,0,,0,0,0,0,,21187,0,0,,0,,3,0,0,0,0,0,0,1,618,1,,,,,,,,,,,,,,,
569797993mS CMCallEvt: 17.67682.0 21187 SIPTrunk Endpoint: StateChange: END=B CMCSRinging->CMCSConnReq
569797993mS CMCallEvt: 5.15.1 21187 Q931 Trunk:5 CHAN=2: StateChange: END=A CMCSRingBack->CMCSOGConnReq
569798003mS CD2: CALL:S 5.15.1,0.67681.0,2,2,1,0,1,0,Line 5,Line 17,,2.3,0.0,100.100,8000@123.12.123.12,0.0,01234123123,,,0,612345,100,,0,16,0,1,8.0,,,,,,,0,362,0,0,0,304,eng,,0,,0,0,0,0,,21187,0,0,,0,,3,0,0,0,0,0,0,1,618,1,,,,,,,,,,,,,,,
569798014mS CMCallEvt: 5.15.1 21187 Q931 Trunk:5 CHAN=2: StateChange: END=A CMCSOGConnReq->CMCSConnected
569798015mS CMTARGET: 5.15.1 21187 Q931 Trunk:5 CHAN=2: ~CMTargetHandler f4a3447c ep f44b3b00
569798016mS CMCallEvt: 17.67682.0 21187 SIPTrunk Endpoint: StateChange: END=B CMCSConnReq->CMCSConnected
569798017mS Sip: 17.67682.0 21187 SIPTrunk Endpoint(f462b458) received CMConnectAck
570414342mS CMCallEvt: 17.67682.0 21187 SIPTrunk Endpoint: StateChange: END=B CMCSConnected->CMCSCompleted
570414346mS CD2: CALL:S 5.15.1,0.67681.0,2,3,1,0,0,0,Line 5,Line 17,,2.3,0.0,100.100,8000@123.12.123.12,0.0,01234123123,,,0,612345,100,,0,16,0,1,8.0,,,,,,,0,616704,0,0,616326,304,eng,,0,,0,0,0,0,,21187,0,0,,0,,3,0,0,0,0,0,0,1,618,1,,,,,,,,,,,,,,,
570414348mS CMCallEvt: END CALL:21187 (f45ad72c)
The above is somewhat sanitised to remove specific numbers etc.
The incoming DDI presented to us is: 612345
The CLI of the call shown is 01234123123
The SIP Switch IP address is 123.12.123.12
The call path as I understand it is, incoming call from network (Q931 channel) presented to 612345 is routed across SIP trunk to DDI of 8000 on the peer SIP system. Under most circumstances this works wonderfully. In some cases, including ones where the CLI is withheld, it doesn't.
If the CLI is withheld and the call is routed in to the Avaya to route directly to another service not going via the SIP trunk then this problem does not occur, so it seems related to the SIP configuration.
For my understanding though, what is happening in the above logs? It seems backwards from what i'd expect? I.e. i'm seeing a "Dial initiated" at the start, and an "Offering" in the middle?
Here's a breakdown of the state changes in the above extract:
569797643mS CMCallEvt: 5.15.1 21187 Q931 Trunk:5 CHAN=2: StateChange: END=A CMCSIdle->CMCSDialInitiated
569797651mS CMCallEvt: 5.15.1 21187 Q931 Trunk:5 CHAN=2: StateChange: END=A CMCSDialInitiated->CMCSDialled
569797652mS CMCallEvt: 0.67681.0 21187 TargetingEP: StateChange: END=B CMCSIdle->CMCSOffering
569797653mS CMCallEvt: 17.67682.0 21187 SIPTrunk Endpoint: StateChange: END=T CMCSIdle->CMCSOffering
569797689mS CMCallEvt: 17.67682.0 21187 SIPTrunk Endpoint: StateChange: END=B CMCSOffering->CMCSRinging
569797690mS CMCallEvt: 5.15.1 21187 Q931 Trunk:5 CHAN=2: StateChange: END=A CMCSDialled->CMCSRingBack
569797993mS CMCallEvt: 17.67682.0 21187 SIPTrunk Endpoint: StateChange: END=B CMCSRinging->CMCSConnReq
569797993mS CMCallEvt: 5.15.1 21187 Q931 Trunk:5 CHAN=2: StateChange: END=A CMCSRingBack->CMCSOGConnReq
569798014mS CMCallEvt: 5.15.1 21187 Q931 Trunk:5 CHAN=2: StateChange: END=A CMCSOGConnReq->CMCSConnected
569798016mS CMCallEvt: 17.67682.0 21187 SIPTrunk Endpoint: StateChange: END=B CMCSConnReq->CMCSConnected
570414342mS CMCallEvt: 17.67682.0 21187 SIPTrunk Endpoint: StateChange: END=B CMCSConnected->CMCSCompleted
Is this only reporting the leg of the call once the decision has been made? Would there be earlier logs related to the original arrival of the call to the system?
Are there specific logging entries that must be enabled to see things more clearly?
Any help appreciated!
Kind Regards
Matt Peddlesden