Modem call progress help

Original log

Jul 11 08:27:44.445: VDEV_ALLOCATE: 1/50 is allocated
Jul 11 08:27:44.445: EVENT_FROM_ISDN: dchan_idb=0x63140240, call_id=0xA5, ces=0x1   bchan=0x1C, event=0x1, cause=0x0
Jul 11 08:27:44.445:  dev in call to isdn : set dnis_collected & fap_notify
Jul 11 08:27:44.445: EVENT_FROM_ISDN:(00A5): DEV_INCALL at slot 1 and port 50
Jul 11 08:27:44.445: EVENT_FROM_ISDN: decode:calling oct3 0x21, called oct3 0xA1, oct3a 0x83,mask 0x27
Jul 11 08:27:44.445: EVENT_FROM_ISDN: csm_call_info:calling oct3 0x21, called oct3 0xA1, oct3a 0x83,mask 0x27
Jul 11 08:27:44.445: PM_ST_MODEM(1/50): modem call_duration_started = 94073
Jul 11 08:27:44.445: CSM_PROC_IDLE: CSM_EVENT_ISDN_CALL at slot 1, port 50
Jul 11 08:27:44.445: CSM DSPLIB(1/50/csm_flags=0x12): np_dsplib_prepare_modem
Jul 11 08:27:44.445: csm_connect_pri_vdev: TS allocated at bp_stream 1, bp_Ch 36, vdev_common 0x627FEE00 1/50
Jul 11 08:27:44.445: PM_ST_MODEM: Incoming modem calling number: #
Jul 11 08:27:44.445: PM_ST_MODEM: Incoming modem called number: #
Jul 11 08:27:44.449: CSM DSPLIB(1/50):DSPLIB_MODEM_INIT: Modem session transition to IDLE
Jul 11 08:27:44.449: CSM DSPLIB(1/50): Modem went offhook
Jul 11 08:27:44.449: CSM_PROC_IC2_RING: CSM_EVENT_MODEM_OFFHOOK at slot 1, port 50
Jul 11 08:27:44.457: VDEV_ALLOCATE: 1/18 is allocated
Jul 11 08:27:44.457: EVENT_FROM_ISDN: dchan_idb=0x63140240, call_id=0xA6, ces=0x1   bchan=0x1B, event=0x1, cause=0x0
Jul 11 08:27:44.457:  dev in call to isdn : set dnis_collected & fap_notify
Jul 11 08:27:44.457: EVENT_FROM_ISDN:(00A6): DEV_INCALL at slot 1 and port 18
Jul 11 08:27:44.457: EVENT_FROM_ISDN: decode:calling oct3 0x21, called oct3 0xA1, oct3a 0x83,mask 0x27
Jul 11 08:27:44.457: EVENT_FROM_ISDN: csm_call_info:calling oct3 0x21, called oct3 0xA1, oct3a 0x83,mask 0x27
Jul 11 08:27:44.457: PM_ST_MODEM(1/18): modem call_duration_started = 94073
Jul 11 08:27:44.457: CSM_PROC_IDLE: CSM_EVENT_ISDN_CALL at slot 1, port 18
Jul 11 08:27:44.457: CSM DSPLIB(1/18/csm_flags=0x12): np_dsplib_prepare_modem
Jul 11 08:27:44.457: csm_connect_pri_vdev: TS allocated at bp_stream 1, bp_Ch 37, vdev_common 0x627F1080 1/18
Jul 11 08:27:44.457: PM_ST_MODEM: Incoming modem calling number: #
Jul 11 08:27:44.457: PM_ST_MODEM: Incoming modem called number: #
Jul 11 08:27:44.457: EVENT_FROM_ISDN: dchan_idb=0x63140240, call_id=0xA5, ces=0x1   bchan=0x1C, event=0x4, cause=0x0
Jul 11 08:27:44.457: EVENT_FROM_ISDN:(00A5): DEV_CONNECTED at slot 1 and port 50
Jul 11 08:27:44.457: CSM_PROC_IC6_WAIT_FOR_CONNECT: CSM_EVENT_ISDN_CONNECTED at slot 1, port 50
Jul 11 08:27:44.457: CSM DSPLIB(1/50): np_dsplib_call_accept
Jul 11 08:27:44.465: CSM DSPLIB(1/18):DSPLIB_MODEM_INIT: Modem session transition to IDLE
Jul 11 08:27:44.465: CSM DSPLIB(1/18): Modem went offhook
Jul 11 08:27:44.465: CSM_PROC_IC2_RING: CSM_EVENT_MODEM_OFFHOOK at slot 1, port 18
Jul 11 08:27:44.465: CSM DSPLIB(1/50):DSPLIB_MODEM_WAIT_ACTIVE: Modem session transition to ACTIVE
Jul 11 08:27:44.465: CSM DSPLIB(1/50): Modem state changed to (CONNECT_STATE)
Jul 11 08:27:44.465: PM_ST_MODEM: State event from 1/50: State = Connect
Jul 11 08:27:44.473: EVENT_FROM_ISDN: dchan_idb=0x63140240, call_id=0xA6, ces=0x1   bchan=0x1B, event=0x4, cause=0x0
Jul 11 08:27:44.473: EVENT_FROM_ISDN:(00A6): DEV_CONNECTED at slot 1 and port 18
Jul 11 08:27:44.473: CSM_PROC_IC6_WAIT_FOR_CONNECT: CSM_EVENT_ISDN_CONNECTED at slot 1, port 18
Jul 11 08:27:44.473: CSM DSPLIB(1/18): np_dsplib_call_accept
Jul 11 08:27:44.477: CSM DSPLIB(1/18):DSPLIB_MODEM_WAIT_ACTIVE: Modem session transition to ACTIVE
Jul 11 08:27:44.477: CSM DSPLIB(1/18): Modem state changed to (CONNECT_STATE)
Jul 11 08:27:44.477: PM_ST_MODEM: State event from 1/18: State = Connect
Jul 11 08:27:48.533: CSM DSPLIB(1/48): Modem state changed to (LINK_STATE)
Jul 11 08:27:48.533: PM_ST_MODEM: State event from 1/48: State = Link
Jul 11 08:27:48.773: CSM DSPLIB(1/51): Modem state changed to (LINK_STATE)
Jul 11 08:27:48.773: PM_ST_MODEM: State event from 1/51: State = Link
Jul 11 08:27:49.049: CSM DSPLIB(1/50): Modem state changed to (LINK_STATE)
Jul 11 08:27:49.049: PM_ST_MODEM: State event from 1/50: State = Link
Jul 11 08:27:49.053: CSM DSPLIB(1/18): Modem state changed to (LINK_STATE)
Jul 11 08:27:49.053: PM_ST_MODEM: State event from 1/18: State = Link
Jul 11 08:27:51.637: CSM DSPLIB(1/48): Modem state changed to (TRAINUP_STATE)
Jul 11 08:27:51.637: PM_ST_MODEM: State event from 1/48: State = Train Up
Jul 11 08:27:51.881: CSM DSPLIB(1/51): Modem state changed to (TRAINUP_STATE)
Jul 11 08:27:51.881: PM_ST_MODEM: State event from 1/51: State = Train Up
Jul 11 08:27:52.145: CSM DSPLIB(1/18): Modem state changed to (TRAINUP_STATE)
Jul 11 08:27:52.145: CSM DSPLIB(1/50): Modem state changed to (TRAINUP_STATE)
Jul 11 08:27:52.149: PM_ST_MODEM: State event from 1/18: State = Train Up
Jul 11 08:27:52.149: PM_ST_MODEM: State event from 1/50: State = Train Up
Jul 11 08:28:05.969: CSM DSPLIB(1/48): Modem state changed to (EC_NEGOTIATING_STATE)
Jul 11 08:28:05.969: PM_ST_MODEM: State event from 1/48: State = EC Negotiating
Jul 11 08:28:06.193: CSM DSPLIB(1/51): Modem state changed to (EC_NEGOTIATING_STATE)
Jul 11 08:28:06.193: PM_ST_MODEM: State event from 1/51: State = EC Negotiating
Jul 11 08:28:06.449: CSM DSPLIB(1/18): Modem state changed to (EC_NEGOTIATING_STATE)
Jul 11 08:28:06.449: PM_ST_MODEM: State event from 1/18: State = EC Negotiating
Jul 11 08:28:06.465: CSM DSPLIB(1/50): Modem state changed to (EC_NEGOTIATING_STATE)
Jul 11 08:28:06.465: PM_ST_MODEM: State event from 1/50: State = EC Negotiating
Jul 11 08:28:06.545: CSM DSPLIB(1/48): Modem state changed to (STEADY_STATE)
Jul 11 08:28:06.545: PM_ST_MODEM: State event from 1/48: State = Steady
Jul 11 08:28:06.569: PM_ST_MODEM: Static event from 1/48
Jul 11 08:28:06.569: connected standard - V.90
Jul 11 08:28:06.569: connected protocol - LAP-M
Jul 11 08:28:06.569: connected compression - None
Jul 11 08:28:06.569: tx_speed/rx_speed : 32000/26400
Jul 11 08:28:06.569: PM_ST_MODEM: SLOT = 1 SPE = 8:
Jul 11 08:28:06.569: Connected Standard = V.90, tx_speed = 32000, rx_speed = 26400
Jul 11 08:28:06.597: PM_ST_MODEM: Dynamic event from 1/48
Jul 11 08:28:06.753: CSM DSPLIB(1/51): Modem state changed to (STEADY_STATE)
Jul 11 08:28:06.753: PM_ST_MODEM: State event from 1/51: State = Steady
Jul 11 08:28:06.781: PM_ST_MODEM: Static event from 1/51
Jul 11 08:28:06.781: connected standard - V.90
Jul 11 08:28:06.781: connected protocol - LAP-M
Jul 11 08:28:06.781: connected compression - None
Jul 11 08:28:06.781: tx_speed/rx_speed : 33333/26400
Jul 11 08:28:06.781: PM_ST_MODEM: SLOT = 1 SPE = 8:
Jul 11 08:28:06.781: Connected Standard = V.90, tx_speed = 33333, rx_speed = 26400
Jul 11 08:28:06.801: PM_ST_MODEM: Dynamic event from 1/51
Jul 11 08:28:07.021: CSM DSPLIB(1/18): Modem state changed to (STEADY_STATE)
Jul 11 08:28:07.021: PM_ST_MODEM: State event from 1/18: State = Steady
Jul 11 08:28:07.033: CSM DSPLIB(1/50): Modem state changed to (STEADY_STATE)
Jul 11 08:28:07.033: PM_ST_MODEM: State event from 1/50: State = Steady
Jul 11 08:28:07.037: PM_ST_MODEM: Static event from 1/18
Jul 11 08:28:07.037: connected standard - V.90
Jul 11 08:28:07.037: connected protocol - LAP-M
Jul 11 08:28:07.037: connected compression - None
Jul 11 08:28:07.037: tx_speed/rx_speed : 33333/26400
Jul 11 08:28:07.037: PM_ST_MODEM: SLOT = 1 SPE = 3:
Jul 11 08:28:07.037: Connected Standard = V.90, tx_speed = 33333, rx_speed = 26400
Jul 11 08:28:07.053: PM_ST_MODEM: Dynamic event from 1/18
Jul 11 08:28:07.057: PM_ST_MODEM: Static event from 1/50
Jul 11 08:28:07.057: connected standard - V.90
Jul 11 08:28:07.057: connected protocol - LAP-M
Jul 11 08:28:07.057: connected compression - None
Jul 11 08:28:07.057: tx_speed/rx_speed : 32000/26400
Jul 11 08:28:07.057: PM_ST_MODEM: SLOT = 1 SPE = 8:
Jul 11 08:28:07.057: Connected Standard = V.90, tx_speed = 32000, rx_speed = 26400
Jul 11 08:28:07.085: PM_ST_MODEM: Dynamic event from 1/50
Jul 11 08:28:07.193: TTY1/48: DSR came up
Jul 11 08:28:07.193: TTY1/48: no timer type 1 to destroy
Jul 11 08:28:07.193: TTY1/48: no timer type 0 to destroy
Jul 11 08:28:07.193: tty1/48: Modem: IDLE->(unknown)
Jul 11 08:28:07.193: TTY1/51: DSR came up
Jul 11 08:28:07.193: TTY1/51: no timer type 1 to destroy
Jul 11 08:28:07.193: TTY1/51: no timer type 0 to destroy
Jul 11 08:28:07.193: tty1/51: Modem: IDLE->(unknown)
Jul 11 08:28:07.193: TTY1/18: DSR came up
Jul 11 08:28:07.193: TTY1/18: no timer type 1 to destroy
Jul 11 08:28:07.193: TTY1/18: no timer type 0 to destroy
Jul 11 08:28:07.193: tty1/18: Modem: IDLE->(unknown)
Jul 11 08:28:07.193: TTY1/50: DSR came up
Jul 11 08:28:07.193: TTY1/50: no timer type 1 to destroy
Jul 11 08:28:07.193: TTY1/50: no timer type 0 to destroy
Jul 11 08:28:07.193: tty1/50: Modem: IDLE->(unknown)

Tool output for modem 1/50