[JAVA] Strano comportamento Try-Catch-Finally

[tylerdurden83]

Posto un estratto di codice:

try {
    ...
    fs = new FileInputStream(this.resource.getResourceFile());
    ...
    while (this.isActive==true) {
        if ((line = input.readLine()) != null) {
      	try {
                 ...
                 this.persist(parsable);
                 ...
                 this.sendJMSMessage((JMSPublishable)parsable);
                 ...
                 continue;
             } catch (Exception e) {
        	    logger.error("Si e' verificata una eccezione durante la persist o la sendJMS del seguente messaggio: "+line, e);
             }
             Thread.sleep(1000L);
             ...
       }
       ...
    }
} catch (SAXException x) {
    logger.error("SAXException while creating the PatternMatchingHandler",x);
} catch (ParserConfigurationException x) {
    logger.error("ParserConfigurationException while creating the PatternMatchingHandler",x);
} catch (InterruptedException x) {
    logger.error("The thread has been interrupted",x);
} catch (FileNotFoundException fnf){
    logger.error("A FileNotFoundException has been raised. It could be a temporary log being destroyed",fnf);
    this.isActive = false;
} catch (IOException ioe) {
    logger.error("A generic IOException has been raised",ioe);
} catch (Exception e) {
    logger.error("Failsafe generic Exception catching",e);
} finally {
    try {
        // clean everything
        ...
        if(fs!=null){fs.close();}                
    } catch (Exception e) {
        logger.error("Some cleaning up in the finally block didn't work",e);
    }
    if (this.isActive==true){
        logger.fatal("A fatal exception has been caught, the whole process is about to be killed");
        System.exit(1);
    } else {
        logger.warn("The thread is about to die. This could be normal in case of a thread running on a temporary log");
    }
}

e il log che ne è uscito fuori:

21:13:57,827 [pool-1-thread-7] [FATAL] implementation.LogTibcoEaimmReader - A fatal exception has been caught, the whole process is about to be killed

In pratica, il controllo è uscito dal

while (this.isActive==true)

sebbene la print successiva confermi che

this.isActive==true

di conseguenza deve esserci stata una exception, eppure nessuna checked exception esplicitamente catturata ha stampato il proprio messaggio (SAXException, ParserConfigurationException, InterruptedException, FileNotFoundException, IOException ioe). Ci potrei anche stare, magari ho preso qualche nullpointer o unchecked runtime exception, tuttavia in coda alle varie checked exception c'è anche una:

} catch (Exception e) {
    logger.error("Failsafe generic Exception catching",e);
} finally {
   ....

e manco questa è stata stampata...eppure nel finally c'è entrato...come potrebbe succedere una cosa del genere?

Grazie a tutti per l'aiuto,
TD

[lupoxxx87]

beh ma la finally viene eseguita anche se entra in uno dei blocchi catch... non è come il default di uno switch che viene eseguito solo se non intercettato prima.

dovresti controllare nel logger.error per capire quale eccezione è stata lanciata...
oppure mettere una print dell'eccezione nello stesso if che ti da la stampa che riscontri.

l'unica cosa che è sicura è che viene lanciata un eccezione durante l'attività dell'oggetto...

[tylerdurden83]

Originariamente inviato da lupoxxx87

beh ma la finally viene eseguita anche se entra in uno dei blocchi catch... non è come il default di uno switch che viene eseguito solo se non intercettato prima.

dovresti controllare nel logger.error per capire quale eccezione è stata lanciata...
oppure mettere una print dell'eccezione nello stesso if che ti da la stampa che riscontri.

l'unica cosa che è sicura è che viene lanciata un eccezione durante l'attività dell'oggetto...

Ho capito, ma infatti è quello che non mi torna, come può essere lanciata una eccezione se:

} catch (Exception e) {
    logger.error("Failsafe generic Exception catching",e);
} finally {
   ....

nel log trovo la print dentro la finally, ma nessuna delle print dentro le catch... L'unica entry nel log è quella della finally, nient'altro... Ah, log4j ovviamente è configurato per stampare da INFO in sù (e lo fa, ho controllato), quindi error non viene filtrato. Per completezza ecco il file di log4j:

log4j.rootLogger=INFO, rootAppender
log4j.appender.rootAppender=org.apache.log4j.DailyRollingFileAppender
log4j.appender.rootAppender.Append=false
log4j.appender.rootAppender.File=test.log
log4j.appender.rootAppender.threshold=TRACE
log4j.appender.rootAppender.layout=org.apache.log4j.PatternLayout
log4j.appender.rootAppender.layout.ConversionPattern=%d{ABSOLUTE} [%t] [%-5p] %C{2} %x - %m%n
log4j.logger.monitoraggiov4=INFO

La print:

21:13:57,827 [pool-1-thread-7] [FATAL] implementation.LogTibcoEaimmReader - A fatal exception has been caught, the whole process is about to be killed

contiene come specificato dal pattern log4j gli ultimi 2 campi del fully qualified class name, implementation.LogTibcoEaimmReader, un package sotto monitoraggioV4 (espressamente settato a INFO in log4j attualmente)

[tylerdurden83]

bumpino....

[banryu79]

Prova a rilanciare ogni eccezione catturata nelle varie clausole catch per vedere quale sia quella che effettivamente viene sollevata (e che non viene loggata?) e/o stampala sullo standard output.

2 Domande banali:
1. dove viene settato a false isActive?
2. c'è solo un thread che accede in scrittura a isActive?

[tylerdurden83]

Originariamente inviato da banryu79

Prova a rilanciare ogni eccezione catturata nelle varie clausole catch per vedere quale sia quella che effettivamente viene sollevata (e che non viene loggata?) e/o stampala sullo standard output.

2 Domande banali:
1. dove viene settato a false isActive?
2. c'è solo un thread che accede in scrittura a isActive?

isActive non viene modoficata da nessuno al momento, ho rimosso la parte che la manipolava x ora. Domani provo quello che mi consigli

[tylerdurden83]

Ieri sera ero un po rinco...

isActive effettivamente non viene mai modificato.

Per quanto riguarda la storia delle print ho pensato che, se entra dentro catch (Exception e), e prova a stamparla ma questa è per qualche motivo null (return nel blocco finally di un metodo precedente?), allora avrei una nullpointerexception che mi fa andare dritto nel finally, giusto?

Ora provo il tuo consiglio dei throw, intanto ieri ho messo delle print senza stampare anche il throwable subito prima di quelle che stampano anche il throwable, queste print di solo testo non possono in alcun modo fallire penso, quindi almeno una dovrebbe comparire...

[tylerdurden83]

Nuovo tentativo...

try {
    ...
    while (true) {
        ...
        super.persist(parsable);
        super.sendJMSMessage((JMSPublishable)parsable);
        ...
    }
} catch (SAXException x) {
    super.logger.fatal("SAXException");
    super.logger.error("SAXException while creating the PatternMatchingHandler",x);
} catch (ParserConfigurationException x) {
    super.logger.fatal("ParserConfigurationException");
    super.logger.error("ParserConfigurationException while creating the PatternMatchingHandler",x);
} catch (InterruptedException x) {
    super.logger.fatal("InterruptedException");
    super.logger.error("The thread has been interrupted",x);
} catch (FileNotFoundException fnf){
    super.logger.fatal("FileNotFoundException");
    super.logger.error("A FileNotFoundException has been raised. It could be a temporary log being destroyed",fnf);
} catch (IOException ioe) {
    super.logger.fatal("IOException");
    super.logger.error("A generic IOException has been raised",ioe);
} catch (Exception e) {
    super.logger.fatal("Exception");
    super.logger.error("Failsafe generic Exception catching",e);
} finally {
    try {
        super.cleanUp();
        if(input!=null){input.close();}
        if(fileReader!=null){fileReader.close();}
        if(fs!=null){fs.close();}                
    } catch (Exception e) {
        super.logger.fatal("Exception nel finally()");
        super.logger.error("Some cleaning up in the finally block didn't work",e);
    }
    super.logger.fatal("A fatal exception has been caught, the whole process is about to be killed");
    System.exit(1);
}

Log:

...
16:35:13,235 [pool-1-thread-7] [FATAL] implementation.LogTibcoEaimmReader - A fatal exception has been caught, the whole process is about to be killed

Ulteriori verifiche nel file di log:

cat test.log_20100614 | grep FATAL
16:35:13,235 [pool-1-thread-7] [FATAL] implementation.LogTibcoEaimmReader - A fatal exception has been caught, the whole process is about to be killed

tail -100 test.log_20100614 | grep ERROR
nessuna entry...

Scusa se non ho ancora provato a rilanciarla ma queste catch sono dentro un metodo run di Runnable.

[banryu79]

Temo di essermi perso qualcosa:

finally {
    ...
    super.logger.fatal("A fatal exception has been caught, the whole process is about to be killed");
    System.exit(1);
}

Perchè scrivi sempre questa entry nel log? E uccidi la vm?

[Kenger]

Non ho capito una cosa... Ti è chiaro il fatto che il programma entra sempre nella finally, sia che ci sia un'eccezione sia che non ci sia?

[tylerdurden83]

Originariamente inviato da banryu79

Temo di essermi perso qualcosa:

finally {
    ...
    super.logger.fatal("A fatal exception has been caught, the whole process is about to be killed");
    System.exit(1);
}

Perchè scrivi sempre questa entry nel log? E uccidi la vm?

Non ho capito cosa intendi sul perchè la scrivo nel log, ti dico perchè uccido la virtual machine. In teoria il thread sta in while(true), non dovrebbe mai smettere di lavorare. Qualora venga presa una di quelle eccezioni (ci sono try catch piu interni per gestire eccezioni in altri punti) il thread deve terminare. In più, invece di avere un thread "worker" in meno e far proseguire l'applicazione con gli altri, viene attualmente preferito far crashare l'applicazione e farla ripartire in automatico.

[tylerdurden83]

Originariamente inviato da Kenger

Non ho capito una cosa... Ti è chiaro il fatto che il programma entra sempre nella finally, sia che ci sia un'eccezione sia che non ci sia?

Certo che mi è chiaro, quello che non mi è chiaro è come possa succedere che

try{
    while(true){
        doStuff();
    }
} catch (Exception e){
    stampa("Eccezione!");
} finally{
    stampa("Finally chiamato");
}

Un codice del genere possa stamparmi nel log solo

"Finally chiamato"

e non

"Eccezione!"
"Finally chiamato"