Re: 3660 with Digital modems progressive failure, cleared with r

Evan Kisbey · ‎12-21-2012

We're fighting an issue with a 3660 router (fitted with a pair ot 2-port T1/E1 cards and four NM-24DM sleds) being used as a dial-up remote access platform. Over time, we see an increasing number of dial-in attempts fail to authenticate.

What happens is the units come up and everything works perfectly; users dial in, they connect, exchange traffic, everyone is happy. Every so often, perhaps every 30 minutes or so, what we'll see is a single modem (for example, the modem in slot 5/10) will begin to experience a large percentage of calls that fail to authenticate, comprising at least 50% of that port's connection attempts, and often 100%:

%CALLRECORD-3-MODEM_CALL_REC_ERROR: DS0 slot/contr/chan=1/1/4, slot/port=5/10, call_id=18E, userid=(n/a), ip=0.0.0.0,

From what we can tell, no authentication attempt actually occurs:

#show debug

General OS:

Modem control/process activation debugging is on

AAA Authentication debugging is on

AAA Accounting debugging is on

AAA Administrative debugging is on

AAA POD packet processing debugging is on

AAA Subsystem debugs debugging is on

AAA API debugs debugging is on

AAA Local debugs debugging is on

AAA Radius debugs debugging is on

Dial on demand:

Dial on demand events debugging is on

CSM Modem Management:

Modem Management Call Switching Module debugging is on

Call Trace Upload:

Call Trace Upload debugging is on

PPP:

PPP authentication debugging is on

MPPE Packet Details debugging is on

PPP protocol errors debugging is on

PPP protocol negotiation debugging is on

PPP packet display debugging is on

PPP forwarding events debugging is on

Multilink events debugging is on

PPP Callback Control Protocol debugging is on

PPP Detailed Elogs debugging is on

Asynchronous interfaces:

Async Rotary Line Queuing Activity debugging is on

Async interface framing debugging is on

Async packet I/O debugging is on

Async interface state changes debugging is on

BAP:

BAP general debugging is on

Modem Relay:

Modem relay errors debugging is on

Modem relay events debugging is on

Modem relay packetizer debugging is on

106719: *Dec 21 12:13:24.113: TTY171: restoring DTR

106720: *Dec 21 12:13:24.113: Modem 5/10 CSM: received ASYNC_DTR_UP for line 171

106733: *Dec 21 12:13:24.865: AAA/API(00000000): aaa_util_unique_id_alloc(), pc 0x601706B8, enter {

106734: *Dec 21 12:13:24.865: AAA/BIND(000016FE): Bind i/f Serial1/0:0

106735: *Dec 21 12:13:24.865: AAA/ACCT/HC(000016FE): Register Se1/0:0 64Kbit/s, poll every 10h 0m 0s

106736: *Dec 21 12:13:24.865: AAA/ACCT/HC(000016FE): Update Se1/0:0

106737: *Dec 21 12:13:24.865: AAA/ACCT/HC(000016FE): Se1/0:0 [init-sess] (rx/tx) base 0/0 pre 0/0 call 0/0

106738: *Dec 21 12:13:24.865: AAA/ACCT/HC(000016FE): Se1/0:0 [init-sess] (rx/tx) adjusted, pre 0/0 call 0/0

106739: *Dec 21 12:13:24.865: AAA/API(00000000): aaa_event_alloc(), pc 0x604D0124 {

106740: *Dec 21 12:13:24.865: AAA/API(00000000): } aaa_event_alloc()

106741: *Dec 21 12:13:24.865: AAA/API(000016FE): aaa_event_send_and_free(), pc 0x604D3F84 {

106742: *Dec 21 12:13:24.869: AAA/ACCT/EVENT/(000016FE): CALL START

106743: *Dec 21 12:13:24.869: Getting session id for NET(000016FE) : db=669A860C

106744: *Dec 21 12:13:24.869: AAA/ACCT(00000000): add node, session 9053

106745: *Dec 21 12:13:24.869: AAA/ACCT/NET(000016FE): add, count 1

106746: *Dec 21 12:13:24.869: AAA/API(000016FE): } aaa_event_send_and_free()

106747: *Dec 21 12:13:24.869: Getting session id for NONE(000016FE) : db=669A860C

106748: *Dec 21 12:13:24.869: AAA/API(000016FE): } aaa_util_unique_id_alloc()

106749: *Dec 21 12:13:24.869: AAA/API(00000000): aaa_event_alloc(), pc 0x6015BA58, enter {

106750: *Dec 21 12:13:24.869: AAA/API(00000000): } aaa_event_alloc()

106751: *Dec 21 12:13:24.869: AAA/API(000016FE): aaa_attr_event_add_string(), pc 0x6015BAA4, enter {

106752: *Dec 21 12:13:24.869: AAA/API(000016FE): } aaa_attr_event_add_string()

106753: *Dec 21 12:13:24.869: AAA/API(000016FE): aaa_attr_event_add_string(), pc 0x6015BAC8, enter {

106754: *Dec 21 12:13:24.869: AAA/API(000016FE): } aaa_attr_event_add_string()

106755: *Dec 21 12:13:24.869: AAA/API(000016FE): aaa_event_send_and_free(), pc 0x601706D4, enter {

106756: *Dec 21 12:13:24.869: AAA/ACCT/EVENT/(000016FE): ATTR REPLACE

106757: *Dec 21 12:13:24.869: AAA/API(00000000): add_attr_to_list(), pc 0x604CBEF4 {

106758: *Dec 21 12:13:24.869: AAA/API(00000000): } add_attr_to_list()

106759: *Dec 21 12:13:24.869: AAA/ACCT(000016FE): Send NEWINFO accounting notification to EM successfully

106760: *Dec 21 12:13:24.869: AAA/API(000016FE): } aaa_event_send_and_free()

106761: *Dec 21 12:13:24.869: CSM: MODEM_REPORT from 1/0:0, call_id=0x18B7, event=0x1, cause=0x0, dchan_idb=0x65B05600

106762: *Dec 21 12:13:24.869: CSM: Next free modem = 5/10; statbits = 80010020

106763: *Dec 21 12:13:24.869: Modem 5/10 CSM: modem is allocated, modems free=0

106764: *Dec 21 12:13:24.869: Modem 5/10 CSM: Incoming call from <removed> to <removed>, id 0x18B7

106765: *Dec 21 12:13:24.869: Modem 5/10 CSM: (CSM_PROC_IDLE)<--ISDN_CALL

106766: *Dec 21 12:13:24.949: CSM: MODEM_REPORT from 1/0:0, call_id=0x18B7, event=0x4, cause=0x0, dchan_idb=0x65B05600

106767: *Dec 21 12:13:24.949: Modem 5/10 CSM: MODEM_REPORT rcvd DEV_CONNECTED for call_id 0x18B7

106768: *Dec 21 12:13:24.949: Modem 5/10 CSM: (CSM_PROC_MODEM_RESERVED)<--ISDN_CONNECTED

106769: *Dec 21 12:13:24.949: Modem 5/10 Mica: configured for Answer mode, with Null signaling, 0x0 tone detection.

106770: *Dec 21 12:13:24.949: %ISDN-6-CONNECT: Interface Serial1/0:0 is now connected to <removed> N/A

106771: *Dec 21 12:13:25.025: %ISDN-6-CHAN_UNAVAILABLE: Interface Se1/0:23 Requested Channel 15 is not available

106772: *Dec 21 12:13:25.049: Modem 5/10 CSM: (CSM_PROC_WAIT_FOR_CARRIER)<--CSM_EVENT_MODEM_SETUP

106773: *Dec 21 12:13:25.049: Modem 5/10 Mica: in modem state CALL_SETUP

106788: *Dec 21 12:13:26.121: Modem 5/10 Mica: in modem state CONNECT

106791: *Dec 21 12:13:26.521: Modem 5/10 Mica: in modem state LINK

106841: *Dec 21 12:13:30.217: Modem 5/10 Mica: in modem state RANGING

106932: *Dec 21 12:13:36.249: Modem 5/10 Mica: in modem state HALF_DUPLEX_TRAIN

106946: *Dec 21 12:13:37.201: Modem 5/10 Mica: in modem state TRAINUP

106983: *Dec 21 12:13:39.653: Modem 5/10 Mica: in modem state EC_NEGOTIATING

107015: *Dec 21 12:13:41.453: Modem 5/10 CSM: (CSM_PROC_WAIT_FOR_CARRIER)<--MODEM_CONNECTED

107016: *Dec 21 12:13:41.453: Modem 5/10 Mica: in modem state STEADY

107017: *Dec 21 12:13:41.453: Modem 5/10 Mica: received ConnectInfo

107018: *Dec 21 12:13:41.453: TTY171: DSR came up

107019: *Dec 21 12:13:41.453: tty171: Modem: IDLE->(unknown)

107020: *Dec 21 12:13:41.457: AAA/LOCAL: exec

107021: *Dec 21 12:13:41.457: TTY171: EXEC creation

107022: *Dec 21 12:13:41.457: AAA/API(00000000): aaa_util_unique_id_alloc(), pc 0x6056C888, enter {

107023: *Dec 21 12:13:41.457: AAA/ACCT/HC(000016FE): Register As171 9Kbit/s, already registered; FAIL

107024: *Dec 21 12:13:41.457: AAA/ACCT/HC(000016FE): Update As171

107025: *Dec 21 12:13:41.457: AAA/ACCT/HC(000016FE): As171 [init-sess] (rx/tx) base 190993/524643 pre 190993/524643 call 190993/524643

107026: *Dec 21 12:13:41.461: AAA/ACCT/HC(000016FE): As171 [init-sess] (rx/tx) adjusted, pre 0/0 call 0/0

107027: *Dec 21 12:13:41.461: AAA/API(000016FE): aaa_attr_update(), pc 0x604CF7AC {

107028: *Dec 21 12:13:41.461: AAA/API(000016FE): } aaa_attr_update()

107029: *Dec 21 12:13:41.461: AAA/API(000016FE): } aaa_util_unique_id_alloc()

107030: *Dec 21 12:13:41.461: AAA/LOCAL: new_ascii_login: tty 658099B0 idb 6580AC30

107031: *Dec 21 12:13:41.461: AAA/API(00000000): aaa_req_alloc(), pc 0x605123F4, enter {

107032: *Dec 21 12:13:41.461: AAA/API(00000000): } aaa_req_alloc()

107033: *Dec 21 12:13:41.461: AAA/AUTHEN/LOGIN (000016FE): Pick method list 'Permanent Local'

107034: *Dec 21 12:13:41.461: AAA SRV(000016FE): process authen req

107035: *Dec 21 12:13:41.461: AAA SRV(000016FE): Authen method=LOCAL

107036: *Dec 21 12:13:41.461: AAA/LOCAL/LOGIN(000016FE): get user

107037: *Dec 21 12:13:41.461: AAA SRV(000016FE): protocol reply GET_USER for Authentication

107038: *Dec 21 12:13:41.461: AAA SRV(000016FE): Return Authentication status=GET_USER

107039: *Dec 21 12:13:41.465: TTY171: create timer type 10, 0 seconds

107040: *Dec 21 12:13:41.473: Modem 5/10 Mica: CONNECT at 33600/28800 (Tx/Rx), V34+, LAPM, V42bis

107047: *Dec 21 12:13:41.937: TTY171: pause timer type 10 (OK)

107048: *Dec 21 12:13:41.937: AAA/API(000016FE): aaa_attr_req_add(), pc 0x60512994, enter {

107049: *Dec 21 12:13:41.937: AAA/API(000016FE): } aaa_attr_req_add()

107050: *Dec 21 12:13:41.941: AAA SRV(000016FE): process authen req

107051: *Dec 21 12:13:41.941: AAA SRV(000016FE): Authen method=LOCAL

107052: *Dec 21 12:13:41.941: AAA/LOCAL/LOGIN(000016FE): get user

107053: *Dec 21 12:13:41.941: AAA SRV(000016FE): protocol reply GET_USER for Authentication

107054: *Dec 21 12:13:41.941: AAA SRV(000016FE): Return Authentication status=GET_USER

107055: *Dec 21 12:13:41.941: TTY171: resume timer type 10 (OK)

107056: *Dec 21 12:13:41.945: TTY171: pause timer type 10 (OK)

107057: *Dec 21 12:13:41.945: AAA/API(000016FE): aaa_attr_req_add(), pc 0x60512994, enter {

107058: *Dec 21 12:13:41.945: AAA/API(000016FE): } aaa_attr_req_add()

107059: *Dec 21 12:13:41.945: AAA SRV(000016FE): process authen req

107060: *Dec 21 12:13:41.945: AAA SRV(000016FE): Authen method=LOCAL

107061: *Dec 21 12:13:41.945: AAA/LOCAL/LOGIN(000016FE): get user

107062: *Dec 21 12:13:41.945: AAA SRV(000016FE): protocol reply GET_USER for Authentication

107063: *Dec 21 12:13:41.945: AAA SRV(000016FE): Return Authentication status=GET_USER

107064: *Dec 21 12:13:41.945: TTY171: resume timer type 10 (OK)

107068: *Dec 21 12:13:42.457: TTY171: timer type 10 expired

107069: *Dec 21 12:13:42.457: TTY171: fg timeout type 10

107070: *Dec 21 12:13:42.473: TTY171: pause timer type 10 (OK)

107071: *Dec 21 12:13:42.473: AAA/API(00000000): aaa_event_alloc(), pc 0x605128B4, enter {

107072: *Dec 21 12:13:42.473: AAA/API(00000000): } aaa_event_alloc()

107073: *Dec 21 12:13:42.473: AAA/API(000016FE): aaa_event_send_and_free(), pc 0x60512910, enter {

107074: *Dec 21 12:13:42.473: AAA/ACCT/EVENT/(000016FE): EXEC DOWN

107075: *Dec 21 12:13:42.473: AAA/API(000016FE): } aaa_event_send_and_free()

107092: *Dec 21 12:13:44.473: TTY171: Line reset by "Exec"

107093: *Dec 21 12:13:44.473: AAA/ACCT/HC(000016FE): Update As171

107094: *Dec 21 12:13:44.473: AAA/ACCT/HC(000016FE): As171 [pre-sess] (rx/tx) base 190993/524643 pre 190993/524643 call 190993/524643

107095: *Dec 21 12:13:44.473: AAA/ACCT/HC(000016FE): As171 [pre-sess] (rx/tx) adjusted, pre 0/0 call 0/0

107096: *Dec 21 12:13:44.473: AAA/ACCT/HC(000016FE): Update As171

107097: *Dec 21 12:13:44.473: AAA/ACCT/HC(000016FE): As171 [sess] (rx/tx) base 190993/524643 pre 190993/524643 call 190993/524643

107098: *Dec 21 12:13:44.473: AAA/ACCT/HC(000016FE): As171 [sess] (rx/tx) adjusted, pre 0/0 call 0/0

107099: *Dec 21 12:13:44.473: AAA/ACCT/HC(000016FE): Deregister As171

107100: *Dec 21 12:13:44.473: TTY171: Modem: (unknown)->HANGUP

107101: *Dec 21 12:13:44.473: TTY171: no timer type 0 to destroy

107102: *Dec 21 12:13:44.473: TTY171: no timer type 1 to destroy

107103: *Dec 21 12:13:44.473: TTY171: no timer type 3 to destroy

107104: *Dec 21 12:13:44.473: TTY171: no timer type 4 to destroy

107105: *Dec 21 12:13:44.473: TTY171: destroy timer type 10

107106: *Dec 21 12:13:44.473: TTY171: no timer type 2 to destroy

107107: *Dec 21 12:13:44.473: AAA/API(00000000): aaa_event_alloc(), pc 0x604D0124, enter {

107108: *Dec 21 12:13:44.473: AAA/API(00000000): } aaa_event_alloc()

107109: *Dec 21 12:13:44.473: AAA/API(000016FE): aaa_event_send_and_free(), pc 0x604D4700, enter {

107110: *Dec 21 12:13:44.473: AAA/ACCT/EVENT/(000016FE): CALL STOP

107111: *Dec 21 12:13:44.473: AAA/ACCT/CALL STOP(000016FE): Sending stop requests

107112: *Dec 21 12:13:44.473: AAA/ACCT(000016FE): Send all stops

107113: *Dec 21 12:13:44.473: AAA/ACCT/NET(000016FE): STOP

107114: *Dec 21 12:13:44.473: AAA/ACCT/NET(000016FE): Method list not found

107115: *Dec 21 12:13:44.473: AAA/ACCT(000016FE): del node, session 9053

107116: *Dec 21 12:13:44.473: AAA/ACCT/NET(000016FE): free_rec, count 0

107117: *Dec 21 12:13:44.473: AAA/ACCT/NET(000016FE) reccnt 0, csr TRUE, osr 0

107118: *Dec 21 12:13:44.473: AAA/ACCT/NET(000016FE): Last rec in db, intf not enqueued

107119: *Dec 21 12:13:44.473: AAA/API(000016FE): } aaa_event_send_and_free()

107120: *Dec 21 12:13:44.477: TTY171: dropping DTR, hanging up

107121: *Dec 21 12:13:44.477: Modem 5/10 CSM: (CSM_PROC_CONNECTED)<--ASYNC_DTR_DOWN

107122: *Dec 21 12:13:44.477: tty171: Modem: HANGUP->(unknown)

107123: *Dec 21 12:13:44.497: Modem 5/10 Mica: in modem state TERMINATING

107124: *Dec 21 12:13:44.497: Modem 5/10 Mica: received TerminateInfo

107125: *Dec 21 12:13:44.513: %ISDN-6-CHAN_UNAVAILABLE: Interface Se1/0:23 Requested Channel 15 is not available

107126: *Dec 21 12:13:44.521: Modem 5/10 CSM: (CSM_PROC_DISCONNECTED)<--MODEM_DISCONNECTED

107127: *Dec 21 12:13:44.521: Modem 5/10 CSM: Stopping dm tone timer

107128: *Dec 21 12:13:44.521: Modem 5/10 Mica: in modem state IDLE

107129: *Dec 21 12:13:44.521: Modem 5/10 CSM: (CSM_PROC_DISCONNECTED)<--QUEUED_DISCONNECT

107130: *Dec 21 12:13:44.525: Modem 5/10 CSM: Stopping dm tone timer

107131: *Dec 21 12:13:44.557: Modem 5/10 CSM: CSM_MODEM_DEALLOCATE: modem is deallocated

107132: *Dec 21 12:13:44.557: TTY171: dropping DTR, hanging up

107133: *Dec 21 12:13:44.557: Modem 5/10 CSM: (CSM_PROC_IDLE)<--ASYNC_DTR_DOWN

107134: *Dec 21 12:13:44.557: tty171: Modem: HANGUP->IDLE

107135: *Dec 21 12:13:44.573: Modem 5/10 Mica: DISCONNECT after 00:00:18, due to reason (0xDF00) Host Disconnect.

107136: *Dec 21 12:13:44.573: %MODEM_HIST-3-END_CALL: Mica Modem 5/10

Connect Protocol - LAPM, Compression - V42bis, Connected Standard - V34+

Tx/Rx bit rate - 33600/28800

Call Time - 00:00:18, Disconnect Reason (0xDF00) - Host Disconnect

0 retrains and/or speed shifts, 1 ec retransmissions requested

1218 chars tx, 45 chars rx, 0 chars rx bad

0 ppp packets tx, 0 ppp packets rx, 0 ppp packets rx bad

12 ec packets tx, 2 ec packets rx, 0 ec packets rx bad

0 v110 packets tx, 0 v110 packets rx

0 v110 packets rx bad, 0 v110 sync loss

107137: *Dec 21 12:13:44.573: %MODEM_HIST-3-END_CALL: Mica Modem 5/10

0 total speedshifts, Total/current MOH time - 0/0 sec, 0 MOH count

Modem not on hold, 0 call waiting retrains, 0 MOH requests

Encoder/Decoder state - Link Compression Not Negotiated/Link Compression Not Negotiated

Tx/Rx compression ratio - 0.00:1/0.00:1

0/0 Tx/Rx dictionary resets

107138: *Dec 21 12:13:44.573: %CALLRECORD-3-MODEM_CALL_REC_ERROR: DS0 slot/contr/chan=1/0/0, slot/port=5/10, call_id=18B7, userid=(n/a), ip=0.0.0.0, calling=<removed>, called=8<removed>, std=V34+, prot=LAPM, comp = V42bis init-rx/tx b-rate=28800/33600, finl-rx/tx b-rate=28800/33600, rbs=0, d-pad=None, retr=0, rx/tx chars=45/1218, bad=0, rx/tx ec=2/12, bad=0, total moh time=0 sec, current moh time=0 sec, moh count=0, moh status=0x0, call waiting retrains=0, moh req=0, encoder/decoder state=0xFF/0xFF, rx/tx comp ratio=0.00:1/0.00:1, rx/tx dict reset=0/0, time=18, finl-state=STEADY, disc(modem)=DF00 Tx (host to line) data flushing - OK/Requested by host/non-s

107139: *Dec 21 12:13:44.577: %ISDN-6-DISCONNECT: Interface Serial1/0:0 disconnected from <removed>, call lasted 19 seconds

#show modem opera 5/10

Modem (5/10) Operational Status:

Parameter #0 Disconnect Reason Info: (0xDF00)

Type (=6 ): Tx (host to line) data flushing - OK

Class (=31): Requested by host

Reason (=0 ): non-specific host disconnect

Parameter #1 Connect Protocol: LAP-M

Parameter #2 Compression: V.44-Both

Parameter #3 EC Retransmission Count: 0

Parameter #4 Self Test Error Count: 0

Parameter #5 Call Timer: 19 secs

Parameter #6 Total Retrains: 0

Parameter #7 Sq Value: 4

Parameter #8 Connected Standard: V.34+

Parameter #9 TX,RX Bit Rate: 33600, 28800

Parameter #11 TX,RX Symbol Rate: 3429, 3429

Parameter #13 TX,RX Carrier Frequency: 1959, 1959

Parameter #15 TX,RX Trellis Coding: 32, 16

Parameter #16 TX,RX Preemphasis Index: 3, 8

Parameter #17 TX,RX Constellation Shaping: On, Off

Parameter #18 TX,RX Nonlinear Encoding: On, Off

Parameter #19 TX,RX Precoding: On, Off

Parameter #20 TX,RX Xmit Level Reduction: 0, 0 dBm

Parameter #21 Signal Noise Ratio: 37 dB

Parameter #22 Receive Level: -19 dBm

Parameter #23 Frequency Offset: 0.125 Hz

Parameter #24 Phase Jitter Frequency: 0.0 Hz

Parameter #25 Phase Jitter Level: 0 degrees

Parameter #26 Far End Echo Level: -36 dBm

Parameter #27 Phase Roll: 0.0 Hz

Parameter #28 Round Trip Delay: 81 msecs

Parameter #30 Characters transmitted, received: 1208, 196

Parameter #32 General Portware Information: 0

Parameter #33 PPP/SLIP packets transmitted, received: 0, 0

Parameter #35 PPP/SLIP packets received (BAD/ABORTED): 0

Parameter #36 EC packets transmitted, received OK: 10, 2

Parameter #38 Moving Average of EC packets (Received BAD/ABORTED): 0

Parameter #39 Robbed Bit Signalling (RBS) pattern: 0

Parameter #40 Digital Pad: None, Digital Pad Compensation: None

Parameter #42 SS7/COT Status: 0

Parameter #43 V110/PIAFS frames received bad: 0

Parameter #44 V110/PIAFS frames received good: 0

Parameter #45 V110/PIAFS frames transmitted: 0

Parameter #46 V110/PIAFS sync lost: 0

Parameter #93 PIAFS RTF: 0

Parameter #120 Total Speedshifts: 0

Parameter #108 Total MOH Time: 0 secs

Parameter #109 Current MOH Time: 0 secs

Parameter #105 MOH Status: Modem is Not on Hold

Parameter #106 MOH Count: 0

Parameter #107 MOH Request Count: 0

Parameter #110 Retrains due to Call Waiting: 0

Parameter #114 DC Encoder,Decoder State: compressed/compressed

Parameter #115 DC TX,RX Compression Ratio: 1.0:1, 1.0:1

Parameter #117 DC TX,RX Dictionary Reset Count: 1, 1

Parameter #119 Diagnostic Code: 00 00 00 00 00 00 00 00

Line Shape:

..........................*

................................*

.................................*

................................*

.................................*

................................*

.................................*

................................*

...............................*

.............................*

............................*

..........................*

......................*

..............*

Once an individual modem enters this state, it behaves in this fashion indefinitely. Shutting the modem down and restarting it has no effect. Only a reload of the chassis seems to have any impact. Once the chassis is reloaded, the behavior is normal for all modems.

After a while -- the time varies -- individual modems will begin experiencing problems again. The individual modems that are affected seem random; they're different each time, but eventaully most of the modems are affected and the chassis must be reloaded.

We have multiple units in mutiple locations that seem to be having this issue.

What could cause it, how could it be prevented, and could there be a method of clearing this state short of reloading the chassis?

krush · ‎12-21-2012

Evan Kisbey wrote:

...

107039: *Dec 21 12:13:41.465: TTY171: create timer type 10, 0 seconds

...

Could this be part of the problem?

Evan Kisbey · ‎12-21-2012

Saw that;

(config-line)#timeout login response 300

results in;

134681: *Dec 21 18:31:13.311: TTY195: create timer type 10, 300 seconds

Call still fails in identical fashion. So while the "0" seconds timer indeed may be symptomatic, it is apparently not the cause...

Evan Kisbey · ‎12-21-2012

Oddly, I've noticed that the autoconfigure string fails on these hung modems:

138048: *Dec 21 18:50:18.553: TTY195: restoring DTR

138049: *Dec 21 18:50:18.553: TTY195: autoconfigure probe started

138050: *Dec 21 18:50:18.553: TTY195: Modem command: --AT&F&D2s29=1--

138056: *Dec 21 18:50:24.729: TTY195: Modem configuration FAILED

138057: *Dec 21 18:50:24.729: TTY195: Done with modem configuration

Going in and trying to force an autoconfigure, I'm left with:

138593: *Dec 21 18:58:49.880: TTY195: No modem found

Shutting the modem, bad, busyout, etc, seem to have no effect... a reboot is all that seems to fix this.

...FYI, Portware 2940 on IOS 12.4(25d)...

Evan Kisbey · ‎12-28-2012

An interesting observation;

When one of the modems goes bad, in order to postpone a reboot and minimize customer impact, we will issue a "modem bad" statement on the afflicted line (for example, line 110) to prevent further calls hitting that modem. Since the line is a member of a group of lines associated with an ansynch group interface prior to this point, adding this statement creates a new "line" stanza in the configuration for the changed modem.

What we're noticing is that stanzas created for the afflicted modems differ from modems that are funcitoning normally. For example, in the following, line 3/13 is not working properly. Line 3/0 is fine. We issue a "modem bad" to line 97 (3/0) and then to 110 (3/13) and observe the results:

#sho run

line 97 120

session-timeout 2 output

absolute-timeout 10

modem InOut

modem autoconfigure type mica-v34production

no editing

autoselect during-login

autoselect ppp

#conf t

(config)#line 97

(config-line)#modem bad

(config-line)#do sho run

line 97

session-timeout 2 output

absolute-timeout 10

modem InOut

modem autoconfigure type mica-v34production

modem bad

no editing

autoselect during-login

autoselect ppp

line 98 120

session-timeout 2 output

absolute-timeout 10

modem InOut

modem autoconfigure type mica-v34production

no editing

autoselect during-login

autoselect ppp

(config-line)#line 110

(config-line)#modem bad

(config-line)#do sho run

line 97

session-timeout 2 output

absolute-timeout 10

modem InOut

modem autoconfigure type mica-v34production

modem bad

no editing

autoselect during-login

autoselect ppp

line 98 109

session-timeout 2 output

absolute-timeout 10

modem InOut

modem autoconfigure type mica-v34production

no editing

autoselect during-login

autoselect ppp

line 110

exec-timeout 0 0

timeout login response 0

modem InOut

modem autoconfigure type mica-v34production

modem bad

data-character-bits 8

exec-character-bits 8

special-character-bits 8

length 0

width 0

no history

no editing

transport preferred none

escape-character soft 0

escape-character 0

no ip tcp input-coalesce-threshold

autoselect during-login

autoselect ppp

hold-character 0

lat out-group all disabled

line 111 120

session-timeout 2 output

absolute-timeout 10

modem InOut

modem autoconfigure type mica-v34production

no editing

autoselect during-login

autoselect ppp

What would cause these additional lines in the configuration? They have to be related somehow!

Evan Kisbey · ‎01-02-2013

So, some progress on this. An individual modem can be restored to function by issuing the following commands, effectively pulling out the altered settings:

session-timeout 2 output

absolute-timeout 10

exec-timeout 0 0

default exec-timeout

default timeout login response

no data-character-bits

exec-character-bits 7

special-character-bits 7

default length

default width

default history size

default history

default editing

default transport preferred

default escape-character soft

default escape-character

ip tcp input-coalesce-threshold 20

default hold-character

default lat out-group

So the question now becomes, what causes these to be altered, and how do I prevent it?

3660 with Digital modems progressive failure, cleared with reload