Caída del motor

Hola a todos!

El sábado a la noche el motor se “colgó”, aunque al hacerle un onstat me indicaba que estaba “on line” y los logical logs estaban vacios (tengo una tarea programada que backupea los logical logs). El domingo hice un onmode -ky y luego el oninit -v.

Tengo una tarea programada que hace el export a las 23.15 hs., y antes de hacer el export baja el motor y lo vuelve a subir.

El log está así:

23:15:00 Shutdown Mode
23:15:01 (110021) connection rejected - too many users, or invalid user name
23:15:01 Quiescent Mode
23:15:02 On-Line Mode
23:15:48 Fuzzy Checkpoint Completed: duration was 0 seconds, 387 buffers not flushed.
23:15:49 Checkpoint loguniq 47334, logpos 0x2c8ca4

23:25:49 Fuzzy Checkpoint Completed: duration was 0 seconds, 387 buffers not flushed.
23:25:49 Checkpoint loguniq 47334, logpos 0x2c9c54

Sun May 12 13:00:41 2013

13:00:41 Checkpoint Completed: duration was 0 seconds.
13:00:41 Checkpoint loguniq 47334, logpos 0x2ca018

13:00:43 Informix Dynamic Server 2000 Stopped.

13:01:11 Informix Dynamic Server 2000 Started.

Sun May 12 13:01:12 2013

13:01:12 Booting Language from module <>
13:01:12 Loading Module
13:01:12 Booting Language from module <>
13:01:12 Loading Module
13:01:17 Informix Dynamic Server 2000 Version 9.21.TC4 Software Serial Number AAD#J203459
13:01:18 Informix Dynamic Server 2000 Initialized – Shared Memory Initialized.

13:01:18 Physical Recovery Started at Page(1:712).
13:01:33 Physical Recovery Complete: 0 Pages Examined 0 Pages Restored.

13:01:33 Logical Recovery Started.
13:01:33 10 recovery worker threads will be started.
13:01:36 Logical Recovery Complete.
0 Committed, 0 Rolled Back, 0 Open, 0 Bad Locks

13:01:36 Dataskip is now OFF for all dbspaces
13:01:36 Init operation complete - Mode Online
13:01:36 On-Line Mode
13:01:37 Checkpoint Completed: duration was 1 seconds.
13:01:37 Checkpoint loguniq 47334, logpos 0x2cb018

13:02:07 Logical Log 47334 - Backup Started
13:02:07 Logical Log 47334 - Backup Completed
13:02:08 Logical Log 47334 Complete.
13:02:08 Logical Log 47335 - Backup Started
13:02:09 Logical Log 47335 - Backup Completed
13:02:09 Logical Log 47335 Complete.
13:02:09 Logical Log 47336 - Backup Started
13:02:09 Logical Log 47336 - Backup Completed
13:02:09 Logical Log 47337 - Backup Started
13:02:09 Logical Log 47337 - Backup Completed
13:02:09 Logical Log 47338 - Backup Started
13:02:09 Logical Log 47338 - Backup Completed
13:02:09 Logical Log 47339 - Backup Started
13:02:09 Logical Log 47339 - Backup Completed
13:02:09 Logical Log 47340 - Backup Started
13:02:10 Logical Log 47340 - Backup Completed
13:02:10 Logical Log 47340 Complete.
13:02:10 Logical Log 47341 - Backup Started
13:02:10 Logical Log 47341 - Backup Completed
13:02:10 Logical Log 47342 - Backup Started
13:02:10 Logical Log 47342 - Backup Completed
13:02:10 Logical Log 47343 - Backup Started
13:02:10 Logical Log 47343 - Backup Completed
13:02:10 Logical Log 47344 - Backup Started
13:02:10 Logical Log 47344 - Backup Completed
13:02:11 Logical Log 47345 - Backup Started
13:02:11 Logical Log 47345 Complete.
13:02:11 Logical Log 47345 - Backup Completed
13:02:11 Logical Log 47346 - Backup Started
13:02:11 Logical Log 47346 - Backup Completed
13:02:11 Logical Log 47347 - Backup Started
13:02:11 Logical Log 47347 - Backup Completed
13:02:11 Logical Log 47348 - Backup Started
13:02:11 Logical Log 47348 - Backup Completed
13:02:11 Logical Log 47349 - Backup Started
13:02:11 Logical Log 47349 - Backup Completed
13:02:12 Logical Log 47350 - Backup Started
13:02:12 Logical Log 47350 Complete.
13:02:12 Logical Log 47350 - Backup Completed
13:02:12 Logical Log 47351 - Backup Started
13:02:12 Logical Log 47351 - Backup Completed
13:02:12 Logical Log 47352 - Backup Started
13:02:12 Logical Log 47352 - Backup Completed
13:02:12 Logical Log 47353 - Backup Started
13:02:12 Logical Log 47353 - Backup Completed
13:02:13 Logical Log 47354 - Backup Started
13:02:13 Logical Log 47354 Complete.
13:02:13 Logical Log 47354 - Backup Completed
13:02:13 Logical Log 47355 - Backup Started
13:02:13 Logical Log 47355 - Backup Completed
13:02:13 Logical Log 47356 - Backup Started
13:02:13 Logical Log 47356 - Backup Completed
13:02:13 Logical Log 47357 - Backup Started
13:02:13 Logical Log 47357 - Backup Completed
13:02:13 Logical Log 47358 - Backup Started
13:02:13 Logical Log 47358 - Backup Completed
13:02:13 Logical Log 47359 - Backup Started
13:02:14 Logical Log 47359 - Backup Completed
13:02:14 Logical Log 47359 Complete.
13:02:14 Logical Log 47360 - Backup Started
13:02:14 Logical Log 47360 - Backup Completed
13:02:14 Logical Log 47361 - Backup Started
13:02:14 Logical Log 47361 - Backup Completed
13:02:14 Logical Log 47362 - Backup Started
13:02:14 Logical Log 47362 - Backup Completed
13:02:14 Logical Log 47363 - Backup Started
13:02:15 Logical Log 47363 - Backup Completed
13:02:15 Logical Log 47363 Complete.
13:02:15 Logical Log 47364 - Backup Started
13:02:15 Logical Log 47364 - Backup Completed
13:02:15 Logical Log 47365 - Backup Started
13:02:15 Logical Log 47365 - Backup Completed
13:02:15 Logical Log 47366 - Backup Started
13:02:15 Logical Log 47366 - Backup Completed
13:02:15 Logical Log 47367 - Backup Started
13:02:16 Logical Log 47367 - Backup Completed
13:02:16 Logical Log 47367 Complete.
13:02:16 Logical Log 47368 - Backup Started
13:02:16 Logical Log 47368 - Backup Completed
13:02:16 Logical Log 47369 - Backup Started
13:02:16 Logical Log 47369 - Backup Completed
13:02:16 Logical Log 47370 - Backup Started
13:02:16 Logical Log 47370 - Backup Completed
13:02:16 Logical Log 47371 - Backup Started
13:02:16 Logical Log 47371 - Backup Completed
13:02:17 Logical Log 47371 Complete.
13:02:17 Logical Log 47372 - Backup Started
13:02:17 Logical Log 47372 - Backup Completed
13:02:17 Logical Log 47373 - Backup Started
13:02:17 Logical Log 47373 - Backup Completed
13:02:17 Logical Log 47374 - Backup Started
13:02:17 Logical Log 47374 - Backup Completed
13:02:17 Logical Log 47375 - Backup Started
13:02:17 Logical Log 47375 - Backup Completed
13:02:18 Logical Log 47376 - Backup Started
13:02:18 Logical Log 47376 Complete.
13:02:18 Logical Log 47376 - Backup Completed
13:02:18 Logical Log 47377 - Backup Started
13:02:18 Logical Log 47377 - Backup Completed
13:02:18 Logical Log 47378 - Backup Started
13:02:18 Logical Log 47378 - Backup Completed
13:02:18 Logical Log 47379 - Backup Started
13:02:18 Logical Log 47379 - Backup Completed
13:02:18 Logical Log 47380 - Backup Started
13:02:18 Logical Log 47380 - Backup Completed
13:02:19 Logical Log 47380 Complete.
13:02:19 Logical Log 47381 - Backup Started
13:02:19 Logical Log 47381 - Backup Completed
13:02:19 Logical Log 47382 - Backup Started
13:02:20 Logical Log 47382 Complete.
13:02:20 Checkpoint Completed: duration was 0 seconds.
13:02:20 Checkpoint loguniq 47383, logpos 0x18

13:02:20 Logical Log 47382 - Backup Completed
13:02:45 Booting Language from module <>
13:02:45 Loading Module
13:12:36 Fuzzy Checkpoint Completed: duration was 0 seconds, 5 buffers not flushed.
13:12:36 Checkpoint loguniq 47383, logpos 0x60d4

13:22:36 Fuzzy Checkpoint Completed: duration was 0 seconds, 5 buffers not flushed.
13:22:36 Checkpoint loguniq 47383, logpos 0x90cc

Se les ocurre que pudo haber pasado??

Gracias.

Saludos.

La tarea que se ejecuta a las 23:15 hs por lo que se ve a esa hora es que se pasa el motor de modo multiusuario (On-line) a modo administrativo o monousuario (Quiescent) y luego a modo multiusuario

23:15:00  Shutdown Mode
23:15:01  (110021) connection rejected - too many users, or invalid user name
23:15:01  Quiescent Mode
23:15:02  On-Line Mode

Hice una prueba de hacer estos mismos pasos y esto es lo que escribe en el log:

00:32:55  Shutdown Mode        
00:32:56  Quiescent Mode
00:33:01  On-Line Mode

Luego el domingo a las 13:00:43 se bajo el motor y un minuto despues se levanto, pareciera ser que en ese momento se apago el servidor y se reinició.

Sun May 12 13:00:41 2013
13:00:41  Checkpoint Completed:  duration was 0 seconds.
13:00:41  Checkpoint loguniq 47334, logpos 0x2ca018
13:00:43  Informix Dynamic Server 2000 Stopped.
13:01:11  Informix Dynamic Server 2000 Started.

Hola Analia,

Una cosa que podria haber pasado, es que el dbexport (por alguna razon) no haya terminado, y dejo la base lockeada. Para confirmar o descartar habria que buscar alguna evidencia de que termino correctamente el dbexport. Intentaste acceder a alguna base ? Que error te daba ?. Los logs no parecen haber estado llenos.

Una cosa, (como ya dijo Ale) la tarea que tenes programada a las 23_15 no baja la base, solo la pone en modo Monousuario (quiescent) y luego la levanta.

Pregunta como disparas el ontape -c que backapea los logs ?. Haces un ontape -s ?

saludos
Ignacio

Analía:

Del análisis de las sentencias del log pareciera que la bajada y arranque del motor para hacer el export a las 23:15 funcionó correctamente. Con que parámetro del onmode la realizás?

También pareciera que el export se debería haber realizado OK (salvo que se demore mucho) ya que a las 23:25 hay un checkpoint, señal que el motor funcionaba. Luego hay otro checkpoint del Domingo a las 13:00:41 justo antes de parar el motor (onmode -ky) y arrancarlo de nuevo. Se podría presumir que el motor en el momento de reiniciarlo aún estaba funcionando y no “colgado”. O no?

A mi en entornos Windows me ha pasado que el motor estaba aparentemente “colgado” para hacer comandos con la consola pero el motor seguia respondiendo a los usuarios. Y otras me ha pasado que el motor no respondía por problemas con la IP (cambios de IP), tipicamente cuando se cortaban las funciones de red y/o Internet.

Quizás microcortes de red que no llegan a voltear la máquina pero si son suficientes para que el Informix no responda más.

Saludos

Gustavo

Alejandro e Ignacio, gracias por contestar.

Sí, me expresé mal. Como dice Alejandro el motor pasa de multiusuario a monousuario y luego vuelve a modo multiusuario. Y entonces hace el dbexport. Esa noche no lo hizo. El dbexport me genera un archivo de salida que, para esa fecha, está vacío.

Al otro día, me avisan que no pueden entrar por 3W a pesar que en el servidor web todo estaba funcionando. Al querer entrar por Gestión, después del usuario y contraseña, tardaba en responder y no me permitió el ingreso.

En ese momento hice un onstat, que me indicaba “on line” y los logical logs vacios. Entonces hice un onmode -ky y luego el oninit -v, que es lo que me indica Alejandro que se hizo el domingo a las 13:00:43. Después de esto, quedó andando.

Me gustaría poder determinar qué pudo haber pasado.

Ignacio, para backapear los logs, tengo una tarea que se inicia a las 23:55,los backupea uno a uno y luego dispara un ontape -c.

Saludos.

Gustavo, gracias por la respuesta.

La bajada y el arranque los hago con onmode -u -y y onmode -m -y. Pero, como les decía, no hizo el dbexport.

En este caso, sería exactamente al revés de lo que te ha pasado en Windows. Los comandos en la consola me los aceptaba, pero no me dejaba entrar como usuario desde una máquina cualquiera. Cambios de IP no se hicieron y no tenemos registro de corte en las funciones de red.

Saludos