How to break std::cout



  • Vielleicht etwas click baity der Titel, aber dies ist die Story wie std::cout bei mir ab und zu den Dienst quittiert hat.
    Ab und zu? Genau, es handelte sich hier nicht um einen deterministischen Ausfall meiner Logging-Ausgaben, sondern nur ein sporadischer, der dann aber dazu führte, dass cout für den Rest des Programms nichts mehr aus gab.
    Was genau ist passiert? Also ich habe, wie so viele andere Leute auch, cout (cerr und clog verhalten sich genauso!) verwendet um Geschehnisse im Terminal zu loggen. Nun verwende ich std::thread und boost::asio um asynchron Operationen auszuführen, und die event handler wurden auch korrekt aufgerufen und ausgeführt. Nur manchmal passierte es, dass irgendwann nichts mehr ins Log geschrieben wurde! Alle folgenden Logging-Aufrufe taten einfach nichts mehr! Was war da los? Zeit für ein

    std::cout.exceptions(std::ios_base::failbit | std::ios_base::badbit);
    

    Und siehe da, manchmal wird dann eine Exception geworfen bei einer Logging-Ausgabe! Es stellt sich heraus, dass manchmal das badbit gesetzt wird. Dabei mache nich nichts spektakuläres: nur Text ausgeben… Was war da los?
    Wenn ich std::cout durch std::printf ersetzt habe, funktionierte es scheinbar immer. Scheinbar. Es fehlten ab und zu mal einige Ausgaben! Natürlich nur seeeehr selten, was mich einige Zeit gekostet hat es heraus zu finden. Aber spätere Ausgaben haben trotzdem funktioniert und nicht wie bei cout, wo dann alles aufgehört hat zu funktionieren (liegt am badbit…). Irgendwann kam ich mal auf die gloreiche Idee den Rückgabewert von printf zu testen. Siehe da, es schlägt manchmal fehl! Leute, prüft eure Rückgabewerte, auch bei Logging-Ausgaben!
    Okay, printf schlägt fehl (puts, fwrite, usw. übrigens auch…), aber warum? Und warum nur sehr selten? Aber das erklärt zumindest, warum cout dann aufgehört hat zu funktionieren, denn es verwendet intern standardmäßig die C IO Funktionen und wenn die fehlschlagen, wird das badbit gesetzt.
    Zeit noch eine Stufe tiefer zu gehen und den nakten Syscall write aufzurufen (ich bin unter Linux unterwegs). Selbes Verhalten wie bei der C IO. Manchmal schlägt der fehl. Hier kann ich nun errno prüfen (darf man das bei den C Funktionen schon?) um heraus zu finden was für ein Fehler vorliegt! Der Übeltäter ist EINTR. Das bedeutet, dass manchmal ein Signal an meinen Prozess geschickt wird und write unterbrochen wird. Wo kommt das Signal her? Keine Ahnung, vermutlich irgendwo in der internen Funktionsweise von std::thread und/oder boost::asio… Denn ohne die ist mir sowas noch nie passiert, und im Internet habe ich auch absolut nichts dazu gefunden.

    Hier ein Testprogramm in C:

    #include <stdio.h>
    #include <signal.h>
    
    static void signal_handler(int sig)
    {
    	(void)sig;
    }
    
    int main(void)
    {
    	struct sigaction sa = {
    		.sa_handler = &signal_handler,
    	};
    	sigemptyset(&sa.sa_mask);
    	if (sigaction(SIGINT, &sa, 0) == -1) {
    		return 1;
    	}
    
    	while (1) {
    		if (puts("line") == EOF) {
    			return 2;
    		}
    	}
    }
    

    Beendet sich nach Ctrl+C mit exit code 2, obwohl ich intuitiv vermutet hätte, dass die C IO Funktionen so schlau sind es nochmal zu probieren. Scheinbar nicht.

    Bin ich der einzige, der dieses Verhalten unintuitiv findet?



  • Der Versuch das Mini Beispiel zu übersetzen ergibt bei mir

    gcc -O2 -std=c17 -Wpedantic -Wall -Wextra signal_handler.c -o signal_handler
    signal.c: In function ‘main’:
    signal.c:9:9: error: variable ‘sa’ has initializer but incomplete type
        9 |  struct sigaction sa = {
          |         ^~~~~~~~~
    signal.c:10:4: error: ‘struct sigaction’ has no member named ‘sa_handler’
       10 |   .sa_handler = &signal_handler,
          |    ^~~~~~~~~~
    signal.c:10:17: warning: excess elements in struct initializer
       10 |   .sa_handler = &signal_handler,
          |                 ^
    signal.c:10:17: note: (near initialization for ‘sa’)
    signal.c:9:19: error: storage size of ‘sa’ isn’t known
        9 |  struct sigaction sa = {
          |                   ^~
    signal.c:12:2: warning: implicit declaration of function ‘sigemptyset’ [-Wimplicit-function-declaration]
       12 |  sigemptyset(&sa.sa_mask);
          |  ^~~~~~~~~~~
    signal.c:13:6: warning: implicit declaration of function ‘sigaction’ [-Wimplicit-function-declaration]
       13 |  if (sigaction(SIGINT, &sa, 0) == -1) {
          |      ^~~~~~~~~
    signal.c:9:19: warning: unused variable ‘sa’ [-Wunused-variable]
        9 |  struct sigaction sa = {
          |                   ^~
    

    Da ist einiges nicht korrekt, auch nicht für ein Minimalbeispiel.



  • Dann fehlt entweder vor den Includes ein

    #define _POSIX_C_SOURCE 200809L
    

    oder mit -D_POSIX_C_SOURCE=200809L kompilieren.



  • @Biolunar sagte in How to break std::cout:

    dass die C IO Funktionen so schlau sind es nochmal zu probieren. Scheinbar nicht.

    Kommt darauf an, ob sa_flags SA_RESTART enthält.



  • @manni66 klar kann man das angeben. Dann müsste ich das aber bei jedem der Signale von 1 bis SIGRTMAX setzen, um dieses Verhalten auch wirklich für jedes Signal zu haben (hab ja keine Ahnung welches kommen könnte). Und SA_RESTART gilt nur für die Syscalls und nicht für die stdio Funktionen.



  • Warum nutzt Du nicht (*sa_sigaction)(int, siginfo_t *, void *); aus dem sigaction struct, so dass Du mehr Informationen bekommst, was da passiert?



  • @john-0 Was soll mir das bringen? Das müsste ja auch für jedes erdenkliche Signal gesetzt werden.



  • @Biolunar sagte in How to break std::cout:

    @john-0 Was soll mir das bringen? Das müsste ja auch für jedes erdenkliche Signal gesetzt werden.

    Das wird nur für das gesetzte signal verwendet. Das geht dann ungefähr so (printf wird in einem echtem Handler nicht wirklich funktionieren).

    #define _POSIX_C_SOURCE 200809L
      
    #include <stdio.h>
    #include <stdlib.h>
    #include <signal.h>
    #include <errno.h>
    #include <string.h>
    
    void sigaction_handler (int signal, siginfo_t* si, void* p) {
        static int v = 0;
        printf("\nsignal: %i\n", signal);
        printf("si_signo: %i\n",si->si_signo);
        printf("si_errno: %i\n",si->si_errno);
        printf("si_code: %i\n",si->si_code);
        v = si->si_pid;
        printf("si_pid: %i\n",v);
        v = si->si_uid;
        printf("si_uid: %i\n",v);
        printf("si_status: %i\n",si->si_status);
        printf("usw.\n");
    
        printf("ucontext address:%p\n",p);
    }
    
    int main(void) {
        int rc = EXIT_SUCCESS;
        const size_t str_length = 1024;
        char* str = malloc(str_length);
    
        struct sigaction sa = {
            .sa_sigaction = &sigaction_handler,
        };
    
        sigemptyset(&sa.sa_mask);
        sigaddset(&sa.sa_mask, SA_SIGINFO);
    
        if (-1 == sigaction(SIGINT, &sa, NULL)) {
            int errnov = errno;
            strerror_r(errnov, str, str_length);
    
            printf("%s\n",str);
            rc = EXIT_FAILURE;
        } else {
            for (;;) {
                /*
                if (EOF == puts("line")) {
                    rc = 2;
                    break;
                }
                */
            }
        }
    
        free(str);
    
        return rc;
    }
    
    


  • @john-0 Ich sehe immer noch nicht was ich dadurch gewinnen soll. Ich habe zwar mehr Infos, aber das hilft mir doch nicht die C und C++ stdlib stabiler zu machen.

    Um die C++ Standard Streams zu reparieren habe ich mir meinen eigenen streambuf geschrieben:

    #include <cerrno>
    #include <cstddef>
    
    #include <streambuf>
    #include <system_error>
    
    #include <unistd.h>
    
    class StreamBuf :
    	public std::streambuf
    {
    	char_type* _buffer = nullptr;
    	std::streamsize _size = 0;
    
    	void writeAll(int fd, void const* data, std::size_t count)
    	{
    		std::size_t written = 0;
    		while (written < count) {
    			ssize_t ret = ::write(fd, static_cast<unsigned char const*>(data) + written, count - written);
    			if (ret < 0) {
    				if (errno == EINTR) {
    					continue;
    				}
    				throw std::system_error{errno, std::system_category(), "write"};
    			}
    			written += static_cast<std::size_t>(ret);
    		}
    	}
    
    protected:
    	std::streambuf* setbuf(char_type* s, std::streamsize n) override
    	{
    		_buffer = s;
    		_size = n;
    		setp(_buffer, _buffer + _size);
    		return this;
    	}
    
    	int sync() override try
    	{
    		auto diff = pptr() - pbase();
    		if (diff < 0) {
    			return -1;
    		} else if (diff > 0) {
    			writeAll(1, pbase(), static_cast<std::size_t>(diff));
    			setp(pbase(), epptr());
    		}
    		return 0;
    	} catch (...) {
    		return -1;
    	}
    
    	int_type overflow(int_type ch = traits_type::eof()) override try
    	{
    		if (sync() == -1) {
    			return traits_type::eof();
    		}
    
    		if (!traits_type::eq_int_type(ch, traits_type::eof())) {
    			char c = traits_type::to_char_type(ch);
    			auto diff = epptr() - pptr();
    			if (diff > 0) {
    				*pptr() = c;
    				pbump(1);
    			} else {
    				writeAll(1, &c, 1);
    			}
    		}
    
    		return traits_type::not_eof(ch);
    	} catch (...) {
    		return traits_type::eof();
    	}
    };
    


  • @Biolunar sagte in How to break std::cout:

    @john-0 Ich sehe immer noch nicht was ich dadurch gewinnen soll. Ich habe zwar mehr Infos, aber das hilft mir doch nicht die C und C++ stdlib stabiler zu machen.

    Ein SIGINT wird Dir nicht ohne Grund zugeschickt! Anstatt nun anzufangen irgend welchen Workarounds zu basteln, solltest Du zuerst abklären weshalb das passiert. Denn üblicherweise gibt es dafür einen sinnvollen Grund.



  • @john-0 ähhh ja. SIGINT hab ich in dem Beispiel nur zu Testzwecken genommen, weil das einfach über die Tastatur erzeugt werden kann. std::thread oder boost::asio verwenden ein anderes Signal zur Inter-Thread-Kommunikation. Ich könnte nun herausfinden welche Signale dort Verwendung finden, und dann? Ich könnte bei diesen dann manuell SA_RESTART als flag setzen, aber das wäre ein Hack von mir. Portabel ist was anderes, denn da würde ich mich auf ein Implementierungsdetail einer Bibliothek verlassen.



  • @Biolunar sagte in How to break std::cout:

    @john-0 ähhh ja. SIGINT hab ich in dem Beispiel nur zu Testzwecken genommen, weil das einfach über die Tastatur erzeugt werden kann. std::thread oder boost::asio verwenden ein anderes Signal zur Inter-Thread-Kommunikation. Ich könnte nun herausfinden welche Signale dort Verwendung finden, und dann?

    Es geht darum die Ursache dafür zu finden, denn irgend was machst Du, was bei IO Probleme verursacht. Du fängst an im Nebel herumzustochern ohne zu wissen was falsch läuft.



  • @Biolunar sagte in How to break std::cout:

    std::thread oder boost::asio verwenden ein anderes Signal zur Inter-Thread-Kommunikation

    Nein



  • std::thread kann ich in der Tat ausschließen. Das lag aber nahe, denn pthread verwendet intern mindestens ein realtime signal.
    Vielleicht liegts an boost::process, denn folgendes Beispiel stürzt recht schnell ab (aber nicht deterministisch):

    #include <cstdlib>
    #include <cstddef>
    
    #include <string>
    #include <iostream>
    #include <exception>
    
    #include <boost/asio.hpp>
    #include <boost/process.hpp>
    
    static boost::asio::io_context ioc;
    static boost::asio::streambuf stdoutBuf;
    static boost::process::async_pipe aop{ioc};
    
    static void onReadStdout(boost::system::error_code const& ec, std::size_t size)
    {
    	if (!ec) {
    		std::cout << "onReadStdout size: " << size;
    
    		std::istream is{&stdoutBuf};
    		std::string line;
    		if (std::getline(is, line)) {
    			std::cout << ", data: " << line;
    		}
    		std::cout << std::endl;
    
    		boost::asio::async_read_until(aop, stdoutBuf, '\n', [] (boost::system::error_code const& err, std::size_t count) { onReadStdout(err, count); });
    	} else {
    		if (ec != boost::asio::error::eof) {
    			std::cout << "onReadStdout ERROR size: " << size << ", error: " << ec << " (" << ec.message() << ")" << std::endl;
    		}
    	}
    }
    
    int main() try
    {
    	std::cout.exceptions(std::ios_base::badbit);
    
    	while (true) {
    		std::cout << "=== BEGIN ===" << std::endl;
    
    		boost::process::child child{"/usr/bin/ls", ioc, boost::process::std_out > aop};
    
    		boost::asio::async_read_until(aop, stdoutBuf, '\n', [] (boost::system::error_code const& ec, std::size_t count) { onReadStdout(ec, count); });
    
    		ioc.run();
    		ioc.restart();
    
    		child.wait();
    
    		aop = boost::process::async_pipe{ioc};
    
    		std::cout << "=== END ===" << std::endl;
    	}
    
    	return EXIT_SUCCESS;
    } catch (std::exception const& err) {
    	std::cerr << "ERROR: " << err.what() << std::endl;
    	return EXIT_FAILURE;
    }
    

    Jetzt wüsste ich gern, was ich falsch mache.



  • Die Lösung ist sehr simpel. Einfach mal das std::endl im Code durch "\n" ersetzen, und dann läuft das Programm. std::endl macht nicht nur einen Zeilenumbruch, sondern flusht auch jedesmal den Ausgabestrom.



  • @john-0 Du hast recht. So scheint es zu laufen…

    Frage mich nur warum? Irgendwann muss der interne buffer doch geflusht werden (sprich es wird der write syscall aufgerufen) und wenn gerade dort das Signal ankommt, müsste das write ja ebenso fehlschlagen. Ich lasse das Testprogramm mal ein paar Stunden laufen, vielleicht stürzt es ja noch irgendwann ab.

    Ich hab noch ein bisschen herumprobiert und das Signal, was da kommt ist SIGCHLD. Es liegt tatsächlich an boost::process, denn dort wird genau auf dieses Signal gewartet. Da standardmäßig fast alle Signale einen Prozess terminieren, wird es wohl in 99,9999% aller Programme nicht auffallen, dass ab und zu mal IO Funktionen einen Fehler zurückliefern. SIGCHLD wird standardmäßig ignoriert, d.h.EINTR wird bei den syscalls gar nicht produziert, aber sobald man auf dieses Signal wartet, kann EINTR auftreten.



  • endl durch '\n' zu ersetzen hilft, denn das Programm läuft nun seit gut zwei Tagen ohne Absturz. Hat jemand eine Erklärung? Oder ist das flushen nun so super selten geworden, dass es mega unwahrscheinlich geworden ist SIGCHLD in dem gleichen Augenblick wie das write zu erhalten? Das ist zumindest meine Vermutung und für meinen Anwendungsfall leider nicht akzeptabel, da das Programm monatelang ohne Neustart laufen soll und nicht zufällig aufhören soll Ausgaben zu produzieren.
    Interessant ist auch, wenn ich die Ausgabe vom Terminal in eine Datei leite (normale Datei oder auch /dev/null), stürzt es auch mit endl nicht ab.


Log in to reply