ich habe zwei recht ähnliche, für einen Kunden mit hohem Telefonieaufkommen relativ schwerwiegende Probleme:
1) Zum einen registriert sich eine SIP-Trunk/Gateway-Leitung über VPN erst nach "gefühlten Ewigkeiten" (3,5 Min.), z. B. nach Verbindungstrennung oder Bootvorgang.
2) Zum anderen registriert sich eine SIP-Trunk/Gateway-Leitung "ewig" (bis zu 30 Min.) nicht wieder, z. B. nach Ausfällen von Routern/Internetzugängen/Telefonanlage/Strom.
Die nachfolgenden Untersuchungen wurden auf einem 1783 vorgenommen mit Firmware 10.12-RU6. Das Problem tritt aber auch mit der 9.24 und anderen Routern mit All-IP/VCM auf. Um Zeitverschiebungen/-ungenauigkeiten auszuschließen wurde der automatische Zeitabgleich vorübergehend deaktiviert.
1) Eine der vielen sehr positiven Eigenschaften der All-IP-Option ist, dass der VCM nach Verbindungstrennungen (z. B. 24-h-Zwangstrennung, DSL-Synchronisationsverlust, kurze Ausfälle der Internetverbindung und sonstige Verbindungstrennungen) und nach Bootvorgängen (z. B. erforderlicher oder geplanter Neustart, Absturz/OS-Panic, Stromausfall) sehr schnell wieder einen funktionalen Betrieb gewährleistet. SIP-Leitungen sind meist zwei oder drei Sekunden nach Verbindungsherstellung wieder registriert, das kann keine Telefonanlage leisten, erst recht nicht bei dynamischer IP-Adresse oder ähnlichen, zwar selten vorkommenden, aber dann meist schwerwiegenden Randbedingungen. Mit einer SIP-Leitung, die über eine VPN-Verbindung zu registrieren ist, tut sich der VCM aber komischerweise sehr schwer. Und da sehe ich keinen Grund für, daher gehe ich von einem Bug aus. Im konkreten Fall baut in einer Filiale ein 1783 eine VPN-Verbindung in die Zentrale auf, wo die Telefonanlage steht. Das REGISTER über diese VPN-Verbindung passiert aber leider nicht schnell genug. Im Syslog (zu Lesen von unten nach oben; aufs Wesentliche gekürzt) kann man das schön nachvollziehen:
Code: Alles auswählen
19:05:18 [VCM] SIP-Line SWYXGW-WAREN switched to status 'registered'
19:02:04 Login from 172.20.172.223 via Telnet-SSL
19:02:04 Login from 172.20.172.223 via Telnet-SSL
19:01:54 Successfully connected to peer RIS-HWI-CC
19:01:54 Successfully connected to peer HGW-7100P
19:01:50 Login from 172.20.172.223 via Telnet-SSL
19:01:50 Login from 172.20.172.223 via Telnet-SSL
...
19:01:48 [VCM] SIP-Line TELEKOM-222278 switched to status 'registered'
19:01:48 Successfully connected to peer HRO-9100P
19:01:46 Successfully connected to peer TELEKOM
19:01:46 local IP address for TELEKOM is 217.92.100.100, remote IP address is 217.0.117.226
...
19:01:38 [VCM] SIP-Line TELEKOM-222278 switched to status 'un-registered'
19:01:38 [VCM] SIP-Line TELEKOM-222278 switched to status 'generic failure'
19:01:38 Accounting list end
19:01:38 User: LANUSER-192.168.180.31 Peer: TELEKOM Rx(kB): 0 Tx(kB): 0 Time(s): 30 Conn: 0
...
19:01:38 User: LANUSER-192.168.180.235 Peer: TELEKOM Rx(kB): 0 Tx(kB): 0 Time(s): 45 Conn: 0
19:01:38 Accounting list start
19:01:38 Disconnected from peer TELEKOM: manual-disconnect
19:01:38 Disconnected from peer RIS-HWI-CC
19:01:38 [VCM] SIP-Line SWYXGW-WAREN switched to status 'un-registered'
19:01:38 Disconnected from peer HGW-7100P
19:01:38 last message repeated 3 times
19:01:38 User from 172.20.172.223 via Telnet-SSL logged out
19:01:38 [VCM] SIP-Line SWYXGW-WAREN switched to status 'generic failure'
19:01:38 Accounting list end
19:01:38 User: LANUSER-192.168.180.31 Peer: HRO-9100P Rx(kB): 1 Tx(kB): 1 Time(s): 10 Conn: 0
...
19:01:38 User: LANUSER-192.168.180.230 Peer: HRO-9100P Rx(kB): 3 Tx(kB): 1 Time(s): 33 Conn: 0
19:01:38 Accounting list start
19:01:38 Disconnected from peer HRO-9100P
19:01:38 VPN: Disconnect info for peer RIS-HWI-CC: physical-disconnected
19:01:38 VPN: Disconnect info for peer RIS-HWI-CC: physical-disconnected
19:01:38 VPN: Disconnect info for peer HGW-7100P: physical-disconnected
19:01:38 VPN: Disconnect info for peer HGW-7100P: physical-disconnected
19:01:38 VPN: Disconnect info for peer HRO-9100P: physical-disconnected
19:01:38 VPN: Disconnect info for peer HRO-9100P: physical-disconnected
19:01:30 Login from 192.168.180.2 via SSH
Im SIP-Packet-Trace ist nichts zu sehen, keine REGISTER-Versuche vor 19:05:18 Uhr. Im Callmanager-Trace sieht man warum. Da wird die Registrierung erst mal um 180 Sekunden verzögert und anschließend noch mal um weitere 30 Sekunden, zusammen 210 Sekunden oder eben 3,5 Minuten. Ich bin der Meinung, dass das ein Bug ist und bitte hiermit um einen Fix. Derzeit springt nach jeder derartigen Situation mein Monitoring an (dieses meldet nicht registrierte SIP-Leitungen nach 2 Minuten).
Callmanager-Trace:
Code: Alles auswählen
19:01:38,086 [SWYXGW-WAREN Registrar Transport]: WAN connection "HRO-9100P" for line "SWYXGW-WAREN" is down! SipLineTransport: 0x04b6abd0
19:01:38,086 [SIP-Provider] : SWYXGW-WAREN: connection down
19:01:38,089 [SIP-Provider] : SWYXGW-WAREN: stopRegistration: this:04b690e0, caller:01cd964c, registration:enabled, register_info:active
19:01:48,047 [SWYXGW-WAREN Registrar Transport]: WAN connection "HRO-9100P" for line "SWYXGW-WAREN" is up! SipLineTransport: 0x04b6abd0
19:01:48,047 [SWYXGW-WAREN Registrar Transport]: Restarting in 180 seconds
19:04:48,047 [SWYXGW-WAREN Registrar Transport]: (Re)Starting with fixed IP address 172.20.172.223
19:04:48,047 [SWYXGW-WAREN Registrar Transport]: New restart backoff is 180 seconds
19:04:48,047 [SWYXGW-WAREN Registrar Transport]: New transport endpoint is 172.20.172.223:5060, transport state is "FixedIpBootstrapping"
19:04:48,048 [SIP-Provider] : SWYXGW-WAREN: registrar transport is ready
19:04:48,048 [SIP-Provider] : SWYXGW-WAREN: startRegistration: this:04b690e0, caller:01cdb92c, registration:enabled, register_info:NOT active
19:04:48,048 [SIP-Provider] : SWYXGW-WAREN: RegisterTimeout: isNotAvailable:no, TimerExpired:no, this:04b690e0
19:04:48,048 [SIP-Provider] : SWYXGW-WAREN: RegisterTimeout: Register finally failed - change to rfc 5626 mode -- backoff status: 0
19:04:48,048 [SIP-Provider] : SWYXGW-WAREN: restartShortRegisterTimer -> time:30000, this:04b690e0, Caller:01cea900
19:04:48,048 [SIP-Provider] : SWYXGW-WAREN: processing pending messages -> registrar transport state:Ready, database is empty
19:04:48,048 [SIP-Provider] : SWYXGW-WAREN: No messages were pending!
19:05:18,048 [SIP-Provider] : SWYXGW-WAREN: RegisterTimeout: isNotAvailable:no, TimerExpired:yes, this:04b690e0
19:05:18,048 [SIP-Provider] : SWYXGW-WAREN: RegisterTimeout:get backoff status: 1
19:05:18,048 [SIP-Provider] : SWYXGW-WAREN: RegisterTimeout: Set backoff timer
19:05:18,048 [SIP-Provider] : SWYXGW-WAREN: RegisterTimeout: eNaUnregister
19:05:18,048 [SIP-Provider] : SWYXGW-WAREN: Unregister: CallId:LANCOM102-172.20.172.223-ed2c2d1f@00a0572e2d44
19:05:18,049 [SIP-Provider] : SWYXGW-WAREN: Unregister: created SIP call
19:05:18,049 [SIP-Provider] : SWYXGW-WAREN: processing pending messages -> registrar transport state:Ready, database has calls
19:05:18,049 [SIP-Provider] : SWYXGW-WAREN: restartShortRegisterTimer -> time:60000, this:04b690e0, Caller:01ceaa70
19:05:18,092 [SIP-Provider] : SWYXGW-WAREN: restartShortRegisterTimer -> time:500, this:04b690e0, Caller:01ceb4c4
19:05:18,593 [SIP-Provider] : SWYXGW-WAREN: RegisterTimeout: isNotAvailable:no, TimerExpired:yes, this:04b690e0
19:05:18,593 [SIP-Provider] : SWYXGW-WAREN: RegisterTimeout:get backoff status: 0
19:05:18,593 [SIP-Provider] : SWYXGW-WAREN: RegisterTimeout: Set backoff timer
19:05:18,593 [SIP-Provider] : SWYXGW-WAREN: RegisterTimeout: Start Timer F
19:05:18,593 [SIP-Provider] : SWYXGW-WAREN: RegisterTimeout: eNaRegister
19:05:18,593 [SIP-Provider] : SWYXGW-WAREN: Register: CallId:LANCOM102-172.20.172.223-ed2c2d1f@00a0572e2d44
19:05:18,593 [SIP-Provider] : SWYXGW-WAREN: Register: created SIP call
19:05:18,593 [SIP-Provider] : SWYXGW-WAREN: processing pending messages -> registrar transport state:Ready, database has calls
19:05:18,593 [SIP-Provider] : SWYXGW-WAREN: restartShortRegisterTimer -> time:1000, this:04b690e0, Caller:01ceaa70
19:05:18,640 [SIP-Provider] : SWYXGW-WAREN: restartShortRegisterTimer -> time:2000, this:04b690e0, Caller:01cea260
19:05:18,689 [SIP-Provider] : Line 'SWYXGW-WAREN' changed status to 'operable'
19:05:18,689 [SIP-Provider] : SWYXGW-WAREN: restartRegisterTimer -> MinExpiresTime:0, time:120000, this:04b690e0, Caller:01ceb14c
Code: Alles auswählen
Echtzeit Zeit Zeitdiff. Versuch Nr.
---------------------------------------------
13:35:42 00:00:00 00:00:00 1
13:35:43 00:00:01 00:00:01 2
13:35:45 00:00:03 00:00:02 3
13:35:49 00:00:07 00:00:04 4
13:35:53 00:00:11 00:00:04 5
13:35:57 00:00:15 00:00:04 6
13:36:01 00:00:19 00:00:04 7
13:36:05 00:00:23 00:00:04 8
13:36:09 00:00:27 00:00:04 9
13:36:13 00:00:31 00:00:04 10
13:39:44 00:04:02 00:03:31 11
13:40:44 00:05:02 00:01:00 12
13:42:44 00:07:02 00:02:00 13
13:46:44 00:11:02 00:04:00 14
13:54:44 00:19:02 00:08:00 15
14:10:44 00:35:02 00:16:00 16
14:40:44 01:05:02 00:30:00 17
15:10:44 01:35:02 00:30:00 18
15:40:44 02:05:02 00:30:00 19
16:10:44 02:35:02 00:30:00 20
Betrachtet man die Tabelle genauer, stellt man auch Unregelmäßigkeiten fest, die meiner Ansicht nach so nicht beabsichtigt sind. Bis zum 10. REGISTER-Versuch ist ja noch alles in Ordnung - sehr gut. Danach wird das REGISTER komplett abgebrochen (sieht man im Callmanager-Trace) und neu gestartet - blöderweise wie bei 1) wieder mit 180 + 30 Sekunden Verzögerung. Gleicher Bug?! Wenn also der Ausfall 31 Sekunden oder mehr beträgt, dauert es schon mal 3,5 Min. bis auch die Telefonie wieder geht. Hat man die Schwelle von 35 Minuten überschritten, wird es richtig ernst. Dann dauert es sage und schreibe bis zu 30 Min. bis ein neues REGISTER angestoßen wird. Das habe ich über mein Monitoring so auch festgestellt, konnte mir aber gar nicht erklären, wodran das liegen soll. Jetzt weiß ich es.
Abschließend noch kurz ein Standort mit CompanyConnect-Leitungen in die Zentrale, d. h. der 1783, der den SIP-Trunk aufnimmt, registriert die SIP-Trunk-Leitung zur Telefonanlage in der Zentrale übers LAN (lokales Routing zum 9100+) und baut somit nicht selber die VPN-Verbindung auf. Man sieht, dass es dann anders läuft, das "3,5-Min.-Problem" ist zumindest da schon mal nicht da. Das grundsätzliche Problem bleibt aber das gleiche.
Code: Alles auswählen
Echtzeit Zeit Zeitdiff. Versuch Nr.
---------------------------------------------
23:36:04 00:00:00 00:00:00 1
23:36:05 00:00:01 00:00:01 2
23:36:07 00:00:03 00:00:02 3
23:36:11 00:00:07 00:00:04 4
23:36:15 00:00:11 00:00:04 5
23:36:19 00:00:15 00:00:04 6
23:36:23 00:00:19 00:00:04 7
23:36:27 00:00:23 00:00:04 8
23:36:31 00:00:27 00:00:04 9
23:36:35 00:00:31 00:00:04 10
23:37:34 00:01:30 00:00:59 11
23:38:34 00:02:30 00:01:00 12
23:40:34 00:04:30 00:02:00 13
23:44:34 00:08:30 00:04:00 14
23:52:34 00:16:30 00:08:00 15
00:08:34 00:32:30 00:16:00 16
00:38:34 01:02:30 00:30:00 17
01:08:34 01:32:30 00:30:00 18
01:38:34 02:02:30 00:30:00 19
02:08:34 02:32:30 00:30:00 20
Vielen Dank und viele Grüße,
Jirka