[JAVA] L'histoire selon laquelle la sortie standard change également fatalement le comportement du programme

Je pense que tout le monde a l'expérience d'ajouter un traitement de sortie standard (comme ʻecho et System.out.print () `) à des scripts et des programmes qui ne fonctionnent pas correctement et de les déboguer. Je pense que l'ajout du traitement de sortie standard est utilisé dans diverses situations, de la simple vérification du fonctionnement du programme à l'enquête dans un environnement où un débogueur ne peut pas être utilisé en raison de restrictions.

Cependant, l'ajout de ** traitement de sortie standard sur 1 ligne peut également changer fatalement le comportement du programme **.

Dans le passé, l'application répondait en ajoutant une ligne de System.out.println (...); au programme Java comme solution de contournement pour le lot bloqué en raison de ** ʻecho`. Il y avait des moments où je ne pouvais pas revenir **. Je voudrais expliquer la mémoire à ce moment-là avec Exemple de programme.

Le lot annuel s'est arrêté!

Il y a environ 10 ans, un jour, j'ai reçu un e-mail de ma part, qui était responsable de la maintenance d'un certain système, disant: «Le lot annuel s'est arrêté, alors dépêchez-vous d'enquêter». Quand je lis le texte plus loin, il dit que le programme est arrêté à la ligne de l'instruction ʻecho dans le fichier batch. ![s1.png](https://qiita-image-store.s3.amazonaws.com/0/43869/914c319b-6923-1178-02d9-55180da8a20d.png) Quand je l'ai entendu pour la première fois, j'ai douté du malentendu du journaliste, mais il est vrai qu'un fichier batch contenant ʻecho avec quatre lignes consécutives (Sample here Il y a k-tamura / stdout-problems / blob / master / src / main / resources / annual.bat)),

・ ・ ・(réduction)・ ・ ・
echo %date% %time% ==================================================>> logs/result.log
echo %date% %time%  [Step4]                                          >> logs/result.log
echo %date% %time%  Pre-Import Processing                            >> logs/result.log
echo %date% %time%                                                   >> logs/result.log
・ ・ ・(réduction)・ ・ ・

Quand j'ai regardé le journal (result.log) qu'il produit, je n'ai vu que deux lignes de messages ʻecho`.

・ ・ ・(réduction)・ ・ ・
2007/09/28 12:04:44.72 ==================================================
2007/09/28 12:04:44.72  [Step4]                                          

(Aucun journal n'a été produit depuis)

J'ai pensé "ce n'est pas possible", mais juste au cas où, j'ai décidé de créer un environnement de test simple et d'exécuter le fichier batch. Le résultat est comme prévu. L'événement n'a pas été reproduit et le processus s'est déroulé normalement. Je ne pouvais penser à rien d'autre que de tuer le processus par lots de l'extérieur.

Après cela, j'ai pu contacter le journaliste par téléphone, alors quand j'ai entendu les détails, il a été dit que ce lot avait été appelé à partir d'un programme Java.

s2.png

Le programme Java que j'ai obtenu du journaliste incluait la méthode main () suivante et démarrait le fichier de commandes avec java.lang.ProcessBuilder ([Sample here](https: //). github.com/k-tamura/stdout-problems/blob/master/src/main/java/org/t246osslab/stdoutproblems/batch/BatchImpl.java)).

import java.io.*;
import org.springframework.core.io.*;

public class BatchImpl implements BatchInterface {

    public static void main(String[] args) {
        System.out.println("Result: " + new BatchImpl().executeBatch());
    }

    public int executeBatch() {
        try {
            Resource resource = new ClassPathResource("annual.bat");
            File batFile = resource.getFile();
            ProcessBuilder pb = new ProcessBuilder(batFile.getAbsolutePath());
            Process process = pb.start();
            return 0;
        } catch (IOException e) {
            e.printStackTrace();
        }
        return -1;
    }
}
* Le code source est beaucoup plus simple que le code réel (à ce moment-là), omettant la gestion des exceptions qui n'a rien à voir avec le problème de cette histoire. ..

Immédiatement, lorsque j'ai exécuté le programme Java, le phénomène s'est reproduit de manière inattendue. Certes, le message "" Traitement avant importation "" n'apparaissait pas après le message "" [Étape 4] "".

Donc, si je supprime ʻecho`, cela fonctionnera-t-il? Je l'ai essayé et ça marche bien. Apparemment, s'il y a plus d'un certain nombre de ** «échos», un événement se produira **.

Trouver

Après avoir confirmé que l'événement peut être reproduit, l'enquête est lancée. Après de nombreuses recherches sur le net, j'ai trouvé une cause qui semble probable. Autrement dit, ** Si le flux de sortie du processus (java.lang.Process) démarré par le programme Java n'est pas lu, le tampon de sortie conservé en interne sera plein et le processus s'arrêtera **. C'est.

process_stop.png

Ainsi, j'ai ajouté une ligne de code qui lit le flux de sortie avec Process.getInputStream () et le sort sur la sortie standard avec System.out.println ().

public int executeBatch() {

    //・ ・ ・(réduction)・ ・ ・

    Process process = pb.start();
    System.out.println(IOUtils.toString(process.getInputStream())); //Ajoutez cette ligne
    return 0;

    //・ ・ ・(réduction)・ ・ ・
}

Ensuite, le lot a commencé à fonctionner correctement sans s'arrêter. Le problème qui était directement causé par le grand nombre de traitements de sortie standard par lots (ʻecho) pouvait être résolu en ajoutant un traitement de sortie standard Java (System.out.println ()`). Sera.

* Pour compléter un peu, vous pouvez sortir dans le journal sans sortir vers la sortie standard avec `System.out.println ()`, et plus De plus, il ignore la valeur de retour, mais il vous suffit d'ajouter ʻIOUtils.toString (process.getInputStream ()); `.
En ce qui concerne le problème que le tampon de sortie est plein, je pense que [cette page](https://www.jpcert.or.jp/java-rules/fio07-j.html) est facile à comprendre.

Maintenant que nous connaissons la cause, nous devons réfléchir à la manière de la traiter, mais nous avons décidé de la laisser aux «gens formidables» qui se réunissent à ce sujet et rentrent chez eux. J'ai pensé: "Cela a résolu ce problème."

Pas de réponse de lot annuel!

Quand je suis allé travailler le lendemain, il y avait un rapport que "la réponse du lot annuel ne revenait pas" que j'aurais dû corriger hier. s3.png La méthode de correction n'est-elle pas différente? J'ai pensé, mais ce n'était pas différent de ce à quoi je m'attendais.

Et j'ai trouvé un autre fait nouveau. Autrement dit, ** le programme Java et le lot annuel que nous avons corrigés hier sont appelés à partir d'une application Web sur un autre hôte via RMI, comme indiqué ci-dessous **. seq1.png

* RMI (Java Remote Method Invocation): Pour communiquer entre des programmes Java via un réseau et appeler des méthodes d'objets (objets distants) sur différents ordinateurs. La technologie.

L'application Web possède un écran similaire à celui qui appelle ce lot et lorsque vous cliquez sur le bouton Exécuter le lot, elle utilise RMI pour exécuter le lot distant de manière asynchrone. L'application Web affiche alors le message "Lot exécuté" à l'utilisateur sans attendre la fin du lot.

Screenshot from 2019-01-28 13-12-19.png

L'application Web envoie alors une demande de confirmation d'achèvement périodique, et après quelques heures la fin du lot, le serveur RMI répond par une réponse d'achèvement avec le message «Lot terminé».

Screenshot from 2019-01-28 13-12-1987.png

Cependant, avec ce correctif, le message "Batch exécuté" n'était pas sorti immédiatement après avoir cliqué sur le bouton "Batch execution" et aucune réponse n'était renvoyée. wait1.gif (Autrement dit, attendez une réponse comme celle-ci dans le navigateur devenu) Compte tenu de ce fait nouveau et des modifications que nous avons apportées hier, il n'a pas fallu longtemps pour en déterminer la cause.

Avant d'ajouter une ligne de System.out.println (・ ・ ・);, le programme Java (= module Java appelé depuis le serveur RMI) a renvoyé une réponse immédiatement, mais après l'avoir ajoutée, Le programme Java était censé renvoyer une réponse après avoir attendu la fin du lot. La raison en est que ** les programmes Java s'exécutent désormais en synchronisation avec le lot en lisant de temps en temps la sortie standard du lot **.

seq2.png

Cette fois, il n'y a pas de problème

Que faire alors?

Puisque la quantité de sortie de «écho» dans le fichier de commandes est importante, la réduction de «écho» est également considérée comme un plan provisoire. C'est également l'une des bonnes options, car il s'agit d'un problème urgent à résoudre, mais ne pas enregistrer n'est pas très bon. De plus, je voudrais prendre des mesures qui prennent en considération l'avenir si possible avec la correction minimale compte tenu de la dégradation (quelqu'un peut ajouter «écho» à des fins de débogage, etc. Puisqu'il n'y en a pas). s4.png Quand j'ai pensé à faire quelque chose de bien, la conclusion était simple. ** Ajoutez la ligne suivante au début du fichier de commandes **.

@echo off

En d'autres termes, j'aurais dû empêcher le lot de sortir en sortie standard.

Comme vous pouvez le voir en exécutant le fichier de commandes à l'invite de commande, les informations (= sortie standard) affichées à l'invite de commande après l'exécution sont ** uniquement la commande exécutée ** comme indiqué ci-dessous.

C:\batch>mkdir logs

C:\batch>echo 2007/09/28 12:04:44.72 ==================================================>> logs/result.log

C:\batch>echo 2007/09/28 12:04:44.73  [Start]                                          >> logs/result.log

C:\batch>echo 2007/09/28 12:04:44.74                                                   >> logs/result.log

C:\batch>echo 2007/09/28 12:04:44.75  Initialize                                      >>logs/result.log

・ ・ ・ (Omis ci-dessous) ・ ・ ・

Toutes les informations que le lot souhaite générer sont redirigées vers le fichier journal (>> logs / result.log), et la sortie standard est des informations inutiles.

5.png

* Pour le fonctionnement de `@ echo off`, voir [Cette page](https://www.adminweb.jp/command/bat/index2.html) Je pense que l'explication est facile à comprendre.

Donc, j'ai ajouté @echo off au début du fichier batch, vérifié qu'il n'y avait pas de problème, et la contre-mesure était terminée pour le moment. s5.png

* L'implémentation du programme Java présenté ci-dessus ne signifie pas qu'il n'y a pas de place pour une révision.

Il y a une réflexion que le travail d'investigation de tous les appelants de la partie corrigée a été omis, mais c'était un événement pour lequel je pensais qu'il serait difficile de corriger un bogue nécessitant une action urgente. Et c'était une expérience rare que j'utilise la sortie standard comme contre-mesure pour l'événement où la sortie standard devenait un problème, et il y avait un autre problème là aussi.

finalement

Il peut être préférable de garder à l'esprit qu '"une ligne de code qui ne semble pas avoir d'effet indésirable à première vue comme le traitement de sortie standard peut fatalement changer le comportement du programme". Peut être.

[Supplément] En fait, essayez

J'ai créé un exemple de programme, donc si vous êtes intéressé, essayez-le. Je l'ai fait sur la base de Spring Boot basé sur la mémoire d'il y a environ 10 ans. Le serveur d'applications et le serveur RMI sont sur le même hôte et sont conçus pour communiquer via localhost.

Puisqu'il s'agit d'un contrôle de fonctionnement, le processus de détection de l'achèvement du lot par l'application Web n'est pas implémenté. De plus, le traitement par lots tel que l'accès à la base de données n'est pas écrit et l'opération par lots est reproduite de manière pseudo en dormant pendant une certaine période de temps.

Matériel de référence

cci95logo.gif

Recommended Posts