Complete output van crashende applicatie afvangen via pipe

[Squee]

Ik heb hier een applicatie waarvan ik de output wil parsen, maar in plaats van normaal te eindigen crashed de app in een segfault. Nu heeft hij op dat moment alle informatie die ik wil hebben al naar STDOUT gestuurd, alleen lukt het me niet om alles goed af te vangen. Als ik het op de commandline start krijg ik alle output die ik nodig heb, maar als ik het door een pipe gooi (bijv naar een bestand, of naar een perl script wat er van leest), dan krijg ik niet alle output die ik krijg op de CLI. Waarschijnlijk omdat het in de pipe gebufferd wordt, en zodra de pipe breekt omdat de app crashed deze buffer niet meer geflushed wordt.

Met ulimit -p zou je aldus de manuals de pipe buffer size moeten kunnen aanpassen, maar dit blijkt hardcoded te zijn, en onveranderbaar.

Heeft iemand misschien nog een truc/idee om dit voor elkaar te krijgen? Helaas is de applicatie closed source en wil hun helpdesk ook niet meewerken aan het fixen van deze bug. (Het gaat om de Adaptec arcconf utility voor het uitlezen van Raid/disk status, maar die crashed zodra hij onze HP Storageworks enclosure tegenkomt op de SCSI bus).

[_Squatt_]

Weet je zeker dat alle output op stdout komt? Het verschil tussen wat je op de commandline ziet en wat er door de pipe komt kan ook komen doordat sommige output op stderr komt.

Probeer:

code:

app > test.txt 2>&1

Dit zorgt ervoor dat alles voor stderr naar stdout wordt geprint. En stdout wordt doorgelusd naar test.txt.

[Squee]

_Squatt_ schreef op dinsdag 16 oktober 2007 @ 17:08:
Weet je zeker dat alle output op stdout komt? Het verschil tussen wat je op de commandline ziet en wat er door de pipe komt kan ook komen doordat sommige output op stderr komt.

Ja dat weet ik zeker, die redirect had ik ook al geprobeerd maar dat mocht niet baten. Ik gok echt dat een buffer/broken pipe probleem is. Het liefst zou ik buffering helemaal uit zetten, maar ik krijg de indruk dat dat niet mogelijk is, behalve als je in de kernel source gaat zitten hacken.

[Squee]

Zie hier het verschl in output, sorry het is een beetje lang:

Direct vanaf een console:

code:

# ./arcconf GETCONFIG 1
Controllers found: 1
----------------------------------------------------------------------
Controller information
----------------------------------------------------------------------
   Controller Status                        : Optimal
   Channel description                      : SCSI
   Controller Model                         : Adaptec 2230S
   Controller Serial Number                 : 171C61
   Physical Slot                            : 5
   Installed memory                         : 128 MB
   Copyback                                 : Disabled
   Background consistency check             : Disabled
   Defunct disk drive count                 : 0
   Logical devices/Failed/Degraded          : 1/0/0
   --------------------------------------------------------
   Controller Version Information
   --------------------------------------------------------
   BIOS                                     : 5.2-0 (11564)
   Firmware                                 : 5.2-0 (11564)
   Driver                                   : 1.1-5 (2442)
   Boot Flash                               : 5.2-0 (11564)
   --------------------------------------------------------
   Controller Battery Information
   --------------------------------------------------------
   Status                                   : Not Installed

----------------------------------------------------------------------
Logical device information
----------------------------------------------------------------------
Logical device number 1
   Logical device name                      : Lo1 Fileserver
   RAID level                               : 5
   Status of logical device                 : Optimal
   Size                                     : 138588 MB
   Read-cache mode                          : Enabled
   Write-cache mode                         : Disabled (write-through)
   Write-cache setting                      : Enabled (write-back)
   Partitioned                              : Yes
   Number of segments                       : 4
   Stripe-unit size                         : 256 KB
   Stripe order (Channel,Device)            : 1,1 1,2 1,3 DHS
   Dedicated Hot-Spare(s)                   : 1,5
   Failed segments                          : No
   Failed stripes                           : No

----------------------------------------------------------------------
Physical Device information
----------------------------------------------------------------------
   Channel #0:
      Transfer Speed                        : Ultra320
      Initiator at SCSI ID 7
      No physical drives attached
   Channel #1:
      Transfer Speed                        : Ultra320
      Initiator at SCSI ID 7
      Device #1
         Device is a Hard drive
         State                              : Online
         Supported                          : Yes
         Transfer Speed                     : Ultra320
         Reported Channel,Device            : 1,1
         Vendor                             : COMPAQ
         Model                              : BD0728A4C4
         Firmware                           : HPB4
         Serial number                      : 3KT549HJ00007702VNR4
         Size                               : 69464 MB
         Write Cache                        : Unknown
         FRU                                : None
         S.M.A.R.T.                         : No
      Device #2
         Device is a Hard drive
         State                              : Online
         Supported                          : Yes
         Transfer Speed                     : Ultra320
         Reported Channel,Device            : 1,2
         Vendor                             : COMPAQ
         Model                              : BD0728A4C4
         Firmware                           : HPB4
         Serial number                      : 3KT4YGPP00007702V5C8
         Size                               : 69464 MB
         Write Cache                        : Unknown
         FRU                                : None
         S.M.A.R.T.                         : No
      Device #3
         Device is a Hard drive
         State                              : Online
         Supported                          : Yes
         Transfer Speed                     : Ultra320
         Reported Channel,Device            : 1,3
         Vendor                             : COMPAQ
         Model                              : BD0728A4C4
         Firmware                           : HPB4
         Serial number                      : 3KT54BGB00007702ULPA
         Size                               : 69464 MB
         Write Cache                        : Unknown
         FRU                                : None
         S.M.A.R.T.                         : No
      Device #5
         Device is a Hard drive
         State                              : Hot Spare
         Dedicated Spare for                : logical device 1
         Supported                          : Yes
         Transfer Speed                     : Ultra320
         Reported Channel,Device            : 1,5
         Vendor                             : COMPAQ
         Model                              : BD0728A4C4
         Firmware                           : HPB4
         Serial number                      : 3KT539ZR00007702UGS1
         Size                               : 69464 MB
         Write Cache                        : Unknown
         FRU                                : None
         S.M.A.R.T.                         : No
      Device #15
         Device is an Enclosure
            Type                            : SAF-TE
            Vendor                          : COMPAQ
            Model                           : PROLIANT 4L7E*DB
            Firmware                        : 2.30
         Status of Enclosure
Segmentation fault

Gepiped door bijv cat:

code:

# ./arcconf GETCONFIG 1 2>&1 |cat
Controllers found: 1
----------------------------------------------------------------------
Controller information
----------------------------------------------------------------------
   Controller Status                        : Optimal
   Channel description                      : SCSI
   Controller Model                         : Adaptec 2230S
   Controller Serial Number                 : 171C61
   Physical Slot                            : 5
   Installed memory                         : 128 MB
   Copyback                                 : Disabled
   Background consistency check             : Disabled
   Defunct disk drive count                 : 0
   Logical devices/Failed/Degraded          : 1/0/0
   --------------------------------------------------------
   Controller Version Information
   --------------------------------------------------------
   BIOS                                     : 5.2-0 (11564)
   Firmware                                 : 5.2-0 (11564)
   Driver                                   : 1.1-5 (2442)
   Boot Flash                               : 5.2-0 (11564)
   --------------------------------------------------------
   Controller Battery Information
   --------------------------------------------------------
   Status                                   : Not Installed

----------------------------------------------------------------------
Logical device information
----------------------------------------------------------------------
Logical device number 1
   Logical device name                      : Lo1 Fileserver
   RAID level                               : 5
   Status of logical device                 : Optimal
   Size                                     : 138588 MB
   Read-cache mode                          : Enabled
   Write-cache mode                         : Disabled (write-through)
   Write-cache setting                      : Enabled (write-back)
   Partitioned                              : Yes
   Number of segments                       : 4
   Stripe-unit size                         : 256 KB
   Stripe order (Channel,Device)            : 1,1 1,2 1,3 DHS
   Dedicated Hot-Spare(s)                   : 1,5
   Failed segments                          : No
   Failed stripes                           : No

----------------------------------------------------------------------
Physical Device information
----------------------------------------------------------------------
   Channel #0:
      Transfer Speed                        : Ultra320
      Initiator at SCSI ID 7
      No physical drives attached
   Channel #1:
      Transfer Speed                        : Ultra320
      Initiator at SCSI ID 7
      Device #1
         Device is a Hard drive
         State                              : Online
         Supported                          : Yes
         Transfer Speed                     : Ultra320
         Reported Channel,Device            : 1,1
         Vendor                             : COMPAQ
         Model                              : BD0728A4C4
         Firmware                           : HPB4
         Serial number                      : 3KT549HJ00007702VNR4
         Size                               : 69464 MB
         Write Cache                        : Unknown
         FRU                                : None
         S.M.A.R.T.                         : No
      Device #2
         Device is a Hard drive
         State                              : Online
         Supported                          : Yes
         Transfer Speed                     : Ultra320
         Reported Channel,Device            : 1,2
         Vendor                             : COMPAQ
         Model                              : BD0728A4C4
         Firmware                           : HPB4
         Serial number                      : 3KT4YGPP00007702V5C8
         Size                               : 69464 MB
         Write Cache                        : Unknown
         FRU                                : None
         S.M.A.R.T.                         : No
      Device #3

En ik zoek dus een manier om de status output van device #3 en #5 te pakken te krijgen, helaas kan je niet bij de utility de status van een enkel device opvragen....

[Super_ik]

kun je niet met strace aan de gang, om te kijken wat er fout gaat
$ strace ./app > app.log

[Squee]

Super_ik schreef op woensdag 17 oktober 2007 @ 15:08:
kun je niet met strace aan de gang, om te kijken wat er fout gaat
$ strace ./app > app.log

Ja, en ik heb ook al eens gdb er aan gehangen en een stack trace gemaakt, maar tsja ik zit zonder de sourcecode en Adaptec wil ook niet meewerken. Ik heb ze nog aangeboden om hun developers te helpen deze bug te fixen maar werd uiteindelijk afgewimpeld met "we supporten geen Debian", terwijl ik vermoed dat dit een generiek probleem is in hun utility.

[deadinspace]

Squee schreef op dinsdag 16 oktober 2007 @ 16:24:
Ik heb hier een applicatie waarvan ik de output wil parsen, maar in plaats van normaal te eindigen crashed de app in een segfault. Nu heeft hij op dat moment alle informatie die ik wil hebben al naar STDOUT gestuurd, alleen lukt het me niet om alles goed af te vangen. Als ik het op de commandline start krijg ik alle output die ik nodig heb, maar als ik het door een pipe gooi (bijv naar een bestand, of naar een perl script wat er van leest), dan krijg ik niet alle output die ik krijg op de CLI. Waarschijnlijk omdat het in de pipe gebufferd wordt, en zodra de pipe breekt omdat de app crashed deze buffer niet meer geflushed wordt.

Het wordt niet in de pipe gebufferd, maar voordat het de pipe ingaat. De pipe is ook geen onderdeel van het process, dus op het moment dat de app crasht is alle data die naar de pipe is weggeschreven veilig. De buffer (die onderdeel is van het process) voor de pipe echter verdwijnt als de app crasht.

Kun je eens de output geven van

ldd ./arcconf

?

Squee schreef op woensdag 17 oktober 2007 @ 17:02:
Ja, en ik heb ook al eens gdb er aan gehangen en een stack trace gemaakt, maar tsja ik zit zonder de sourcecode en Adaptec wil ook niet meewerken. Ik heb ze nog aangeboden om hun developers te helpen deze bug te fixen maar werd uiteindelijk afgewimpeld met "we supporten geen Debian", terwijl ik vermoed dat dit een generiek probleem is in hun utility.

Lekker dan
Dan weet je in ieder geval van wie je volgende keer geen hardware hoeft te kopen (en dat kun je ze ook gerust laten weten trouwens).

[Squee]

ldd output, zoals gevraagd

code:

# ldd arcconf
        linux-gate.so.1 =>  (0xb7f57000)
        libdl.so.2 => /lib/tls/libdl.so.2 (0xb7f4b000)
        libpthread.so.0 => /lib/tls/libpthread.so.0 (0xb7f39000)
        libstdc++.so.5 => /usr/lib/libstdc++.so.5 (0xb7e7e000)
        libm.so.6 => /lib/tls/libm.so.6 (0xb7e59000)
        libgcc_s.so.1 => /lib/libgcc_s.so.1 (0xb7e4e000)
        libc.so.6 => /lib/tls/libc.so.6 (0xb7d1c000)
        /lib/ld-linux.so.2 (0xb7f58000)

deadinspace schreef op woensdag 17 oktober 2007 @ 19:04:
Het wordt niet in de pipe gebufferd, maar voordat het de pipe ingaat. De pipe is ook geen onderdeel van het process, dus op het moment dat de app crasht is alle data die naar de pipe is weggeschreven veilig. De buffer (die onderdeel is van het process) voor de pipe echter verdwijnt als de app crasht.

Nee pipes hebben wel degelijk een buffer, standaard is dat 4096 bytes. Zie ook:

code:

# ulimit -p
8

(is in 512-byte blocks)

[ Voor 36% gewijzigd door Squee op 17-10-2007 20:35 ]

[deadinspace]

Squee schreef op woensdag 17 oktober 2007 @ 20:32:

code:

# ldd arcconf
        linux-gate.so.1 =>  (0xb7f57000)
        libdl.so.2 => /lib/tls/libdl.so.2 (0xb7f4b000)
        libpthread.so.0 => /lib/tls/libpthread.so.0 (0xb7f39000)
        libstdc++.so.5 => /usr/lib/libstdc++.so.5 (0xb7e7e000)
        libm.so.6 => /lib/tls/libm.so.6 (0xb7e59000)
        libgcc_s.so.1 => /lib/libgcc_s.so.1 (0xb7e4e000)
        libc.so.6 => /lib/tls/libc.so.6 (0xb7d1c000)
        /lib/ld-linux.so.2 (0xb7f58000)

Ok, mooi, hij is dynamisch gelinkt. Dan vermoed ik dat we er wel de juiste info uit kunnen krijgen.

Zou je eens met

ltrace ./arcconf

willen kijken welke library call hij gebruikt om die informatie te printen?

Nee pipes hebben wel degelijk een buffer, standaard is dat 4096 bytes.

Ja, dat klopt; ik was niet erg precies met mijn opmerking.

Pipes zijn zelf inderdaad een buffer, maar dat is niet wat hier het probleem is. Informatie die daadwerkelijk naar de pipe is weggeschreven is veilig en raakt niet meer zoek op het moment dat de app crasht.

Het probleem is dat er ook gebufferd wordt binnen het process zelf (namelijk in libc; printf() en vriendjes zijn bufferend), voordat het de pipe ingaat. Die buffer is wèl kwijt op het moment dat de app crasht.

[Squee]

deadinspace schreef op woensdag 17 oktober 2007 @ 21:07:
Zou je eens met

ltrace ./arcconf

willen kijken welke library call hij gebruikt om die informatie te printen?

Eerlijkgezegd zie ik de messages die hij print niet terug in de ltrace, dus het is me ook niet duidelijk hoe hij dat print. Dit is iig het laatste stukje van de ltrace output voordat hij crashed: (en om het nog verwarrender te maken, het programma is nog multithreaded ook...)

code:

strrchr("/sys/class/scsi_host/host2/proc_"..., '/') = "/proc_name"
access("/sys/class/scsi_host/host2/flags", 4)    = 0
fopen("/sys/class/scsi_host/host2/flags", "r")   = 0x816af68
fgets("SAI_READ_CAPACITY_16\n", 256, 0x816af68)  = 0xbf93fdd0
strstr("SAI_READ_CAPACITY_16\n", "SAI_READ_CAPACITY_16") = "SAI_READ_CAPACITY_16\n"
fclose(0x816ad50)                                = 0
fclose(0x816ae00)                                = 0
fclose(0x816af68)                                = 0
strncpy(0xbf93fed0, "PopulateOSIndependentPartAdapter"..., 255) = 0xbf93fed0
access("/var/log/fsaapi.txt", 6)                 = -1
mbstowcs(0xbf940e04, 0xbf940ec0, 14, -1, 0)      = 13
access("/var/log/fsaapi.txt", 6)                 = -1
wcsncpy(0x816a0b8, 0xbf940e04, 17, 0, 0)         = 0x816a0b8
ioctl(3, 270344, 0xbf940c20)                     = 0
malloc(12)                                       = 0x816ac20
ioctl(3, 270572, 0x816ac20)                      = 0
free(0x816ac20)                                  = <void>
sprintf("[unknown CTCOMMAND:193]", "[unknown CTCOMMAND:%d]", 193) = 23
ioctl(3, 270344, 0xbf93f770)                     = 0
sprintf("[unknown CTCOMMAND:190]", "[unknown CTCOMMAND:%d]", 190) = 23
ioctl(3, 270344, 0xbf93f790)                     = 0
memcpy(0xbf940018, "\002", 8)                    = 0xbf940018
memcpy(0xbf93fdc4, "", 156)                      = 0xbf93fdc4
sprintf("[unknown TFib, Header.Size:176]", "[unknown TFib, Header.Size:%d]", 176) = 31
ioctl(3, 270344, 0xbf93fd90)                     = 0
memcpy(0xbf940a20, "\001", 156)                  = 0xbf940a20
ioctl(3, 270344, 0xbf93f790)                     = 0
ioctl(3, 270344, 0xbf93f790)                     = 0
memcpy(0xbf940ac0, "\001", 288)                  = 0xbf940ac0
ioctl(3, 270344, 0xbf93f790)                     = 0
ioctl(3, 270344, 0xbf93f750)                     = 0
memcpy(0xbf940be0, "", 48)                       = 0xbf940be0
ioctl(3, 270344, 0xbf940820)                     = 0
ioctl(3, 270344, 0xbf93f790)                     = 0
ioctl(3, 270620, 0xbf93ffd0)                     = 0
strncpy(0xbf93fee0, "AIF_StartThreadProcessing", 255) = 0xbf93fee0
access("/var/log/fsaapi.txt", 6)                 = -1
malloc(28)                                       = 0x816ac30
sem_init(0x816ac38, 0, 0, 0x813a0f1, 28)         = 0
sem_getvalue(0x816ac38, 0xbf93feac, 0, 0x813a0f1, 28) = 0
malloc(28)                                       = 0x816ad50
sem_init(0x816ad58, 0, 0, 0x813a0f1, 28)         = 0
sem_getvalue(0x816ad58, 0xbf93feac, 0, 0x813a0f1, 28) = 0
malloc(28)                                       = 0x816ad70
sem_init(0x816ad78, 0, 0, 0x813a0f1, 28)         = 0
sem_getvalue(0x816ad78, 0xbf93feac, 0, 0x813a0f1, 28) = 0
pthread_attr_init(0xbf93fe90, 16, 3, 0x813a3db, 0) = 0
pthread_attr_setdetachstate(0xbf93fe90, 1, 3, 0x813a3db, 0) = 0
pthread_create(0xbf93fe8c, 0xbf93fe90, 0x80c5cf0, 0x8169cc4, 0xbf93fe90 <unfinished ...>
+++ killed by SIGTRAP +++

En laatste stukje van een strace:

code:

write(1, "      Device #5\n", 16)       = 16
write(1, "         Device is a Hard drive\n", 32) = 32
write(1, "         State                  "..., 56) = 56
write(1, "         Dedicated Spare for    "..., 63) = 63
write(1, "         Supported              "..., 50) = 50
write(1, "         Transfer Speed         "..., 55) = 55
write(1, "         Reported Channel,Device"..., 50) = 50
write(1, "         Vendor                 "..., 53) = 53
write(1, "         Model                  "..., 57) = 57
write(1, "         Firmware               "..., 51) = 51
write(1, "         Serial number          "..., 67) = 67
write(1, "         Size                   "..., 55) = 55
write(1, "         Write Cache            "..., 54) = 54
write(1, "         FRU                    "..., 51) = 51
write(1, "         S.M.A.R.T.             "..., 49) = 49
write(1, "      Device #15\n", 17)      = 17
write(1, "         Device is an Enclosure\n", 32) = 32
write(1, "            Type                "..., 53) = 53
write(1, "            Vendor              "..., 53) = 53
write(1, "            Model               "..., 63) = 63
write(1, "            Firmware            "..., 51) = 51
write(1, "         Status of Enclosure\n", 29) = 29
--- SIGSEGV (Segmentation fault) @ 0 (0) ---
+++ killed by SIGSEGV +++

En dan nog wat gdb output:

code:

(gdb) info threads
  2 Thread -1210885200 (LWP 11282)  0xb7df9fd9 in poll ()
   from /lib/tls/libc.so.6
* 1 Thread -1210877056 (LWP 11276)  0x0806c3ba in SafteConfig::getFanCount ()
(gdb) thread 1
[Switching to thread 1 (Thread -1210877056 (LWP 11276))]#0  0x0806c3ba in SafteConfig::getFanCount ()
(gdb) bt
#0  0x0806c3ba in SafteConfig::getFanCount ()
#1  0x0808aad1 in Enclosure::getFanCount ()
#2  0x0804f2b9 in printEnclosure ()
#3  0x0804f43b in printChannel ()
#4  0x08054f03 in GetConfig::execute ()
#5  0x08052873 in FunctionResolver::executeOrShowHelp ()
#6  0x08052233 in main ()
(gdb) thread 2
[Switching to thread 2 (Thread -1210885200 (LWP 11282))]#0  0xb7df9fd9 in poll
    () from /lib/tls/libc.so.6
(gdb) bt
#0  0xb7df9fd9 in poll () from /lib/tls/libc.so.6
#1  0x08101dfe in faos_Sleep ()
#2  0x081001a6 in faos_GetAIF ()
#3  0x080c5c05 in AdapterWaitAndGetAsyncFib ()
#4  0x080e737d in InternalWaitAndGetAsyncFib ()
#5  0x080c5d32 in AIF_FibThreadProcessing ()
#6  0xb7f5a0bd in start_thread () from /lib/tls/libpthread.so.0
#7  0xb7e03ace in clone () from /lib/tls/libc.so.6

Als je dit weet op te lossen ben je echt een held. Ik zit me hier echt al een aantal weken over te frustreren. (o.a. ook omdat hun helpdesk koppig en traag was)

[deadinspace]

Squee schreef op donderdag 18 oktober 2007 @ 00:26:
Eerlijkgezegd zie ik de messages die hij print niet terug in de ltrace, dus het is me ook niet duidelijk hoe hij dat print. Dit is iig het laatste stukje van de ltrace output voordat hij crashed: (en om het nog verwarrender te maken, het programma is nog multithreaded ook...)

code:

[...]
pthread_create(0xbf93fe8c, 0xbf93fe90, 0x80c5cf0, 0x8169cc4, 0xbf93fe90 <unfinished ...>
+++ killed by SIGTRAP +++

Ai, ltrace kan geen threaded applicaties tracen volgens deze mail. Die SIGTRAP klopt goed met die informatie.

En laatste stukje van een strace:

En als je hem straced terwijl je de output door cat piped (strace ./arcconf | cat), krijg je die write()s voor die laatste regels dan ook te zien, of ontbreken die voor de laatste regels dan?

Het is ook C++ zie ik. Dat (samen met het multithreaded zijn) maakt het moeil... eh, uitdagender

edit:
Al zie ik wel dat de ltrace output een hoop C library calls bevat. Als ze ook C functies gebruiken voor de output in plaats van de C++ mechanismen, dan is het waarschijnlijk weer wat makkelijker.

Kun je misschien dat tooltje ergens online zetten, of me wijzen waar ik eraan kan komen (het liefst exact dezelfde versie als die jij gebruikt)?

[ Voor 8% gewijzigd door deadinspace op 18-10-2007 01:16 ]

[Squee]

deadinspace schreef op donderdag 18 oktober 2007 @ 01:01:
En als je hem straced terwijl je de output door cat piped (strace ./arcconf | cat), krijg je die write()s voor die laatste regels dan ook te zien, of ontbreken die voor de laatste regels dan?

Ik krijg dan inderdaad de korte variant van de output, maar ook in de strace zie ik de hele zwik writes niet terug. Alleen de eerste lijkt er dan nog uit te komen, terwijl de rest toch wel degelijk geprint wordt.

Hij eindigt dan zo:

code:

stat64("/sys/class/scsi_host/host28/proc_name", 0xbfb590d0) = -1 ENOENT (No such file or directory)
stat64("/sys/class/scsi_host/host29/proc_name", 0xbfb590d0) = -1 ENOENT (No such file or directory)
stat64("/sys/class/scsi_host/host30/proc_name", 0xbfb590d0) = -1 ENOENT (No such file or directory)
stat64("/sys/class/scsi_host/host31/proc_name", 0xbfb590d0) = -1 ENOENT (No such file or directory)
unlink("/dev/aac15")                    = -1 ENOENT (No such file or directory)
close(4)                                = 0
open("/dev/aac15", O_RDONLY)            = -1 ENOENT (No such file or directory)
access("/var/log/fsaapi.txt", R_OK|W_OK) = -1 ENOENT (No such file or directory)
access("/var/log/fsaapi.txt", R_OK|W_OK) = -1 ENOENT (No such file or directory)
access("/var/log/fsaapi.txt", R_OK|W_OK) = -1 ENOENT (No such file or directory)
fstat64(1, {st_mode=S_IFIFO|0600, st_size=0, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7fa2000
write(1, "Controllers found: 1\n-----------"..., 4096) = 4096

Waarbij die write de laatste output van de strace is, terwijl het de eerste write van de output is. Daarna komt nog de zwik output tot de header van Device #3, en dan de segfault message. (beetje redundant om dat nog een keer hier te copy/pasten)

Kun je misschien dat tooltje ergens online zetten, of me wijzen waar ik eraan kan komen (het liefst exact dezelfde versie als die jij gebruikt)?

http://www.mwvantol.dds.nl/arcconf (1.3MB)

[sam.vimes]

Kijk eens naar programma 'script'; dit maakt een dump van alles wat er op je scherm verschijnt:

 NAME
      script - make typescript of terminal session
 SYNOPSIS
      script [-a] [file]
 DESCRIPTION
      script makes a typescript of everything printed on your terminal.  It
      starts a shell named by the SHELL environment variable, or by default
      /usr/bin/sh, and silently records a copy of output to your terminal
      from that shell or its descendents, using a pseudo-terminal device
      (see pty(7)).

[Squee]

sam.vimes schreef op donderdag 18 oktober 2007 @ 09:22:
Kijk eens naar programma 'script'; dit maakt een dump van alles wat er op je scherm verschijnt:

Hee dat klinkt veelbelovend:

     -c COMMAND
             Run the COMMAND rather than an interactive shell.  This makes it
             easy for a script to capture the output of a program that behaves
             differently when its stdout is not a tty.

En het leek ook te werken toen ik het net even probeerde vanaf de commandline. Ik ga vanmiddag kijken of ik het ook goed vanuit perl kan scripten, dan weten we meteen of dit de oplossing is!

[ Voor 24% gewijzigd door Squee op 18-10-2007 11:17 ]

[deadinspace]

Squee schreef op donderdag 18 oktober 2007 @ 08:33:
Ik krijg dan inderdaad de korte variant van de output, maar ook in de strace zie ik de hele zwik writes niet terug. Alleen de eerste lijkt er dan nog uit te komen, terwijl de rest toch wel degelijk geprint wordt.

Ok, dat komt dus omdat glibc anders buffert als de applicatie op een terminal draait dan wanneer de output door een pipe gestuurd wordt. Stukje relevante glibc documentatie:

There are three different kinds of buffering strategies:

• Characters written to or read from an unbuffered stream are transmitted individually to or from the file as soon as possible.
• Characters written to a line buffered stream are transmitted to the file in blocks when a newline character is encountered.
• Characters written to or read from a fully buffered stream are transmitted to or from the file in blocks of arbitrary size.

Newly opened streams are normally fully buffered, with one exception: a stream connected to an interactive device such as a terminal is initially line buffered. [...]

En hier documentatie over functies om dat gedrag te wijzigen.

Aan de hand daarvan heb ik een wrapper library gemaakt die het buffering-gedrag van een programma tijdens het draaien aanpast naar line-buffered:

C:

#include <stdio.h>
#include <dlfcn.h>



/* unbuffer - set an application's stdout to line buffered at runtime.
 *
 * This is a small malloc() wrapper that will set stdout of the current
 * process to line buffered the first time it's called. It's intended to
 * be used as a preloaded dynamic library.
 *
 * Compile:   cc -Wall -O2 -fpic -shared -ldl -o unbuffer.so unbuffer.c
 * Run:       LD_PRELOAD=./unbuffer.so ./application
 */



void *malloc( size_t size )
{
        static void *(*real_malloc)( size_t ) = NULL;

        if( !real_malloc )
        {
                real_malloc = dlsym( (void *) -1, "malloc" );
                setvbuf( stdout, (char *) NULL, _IOLBF, 0 );
        }

        return real_malloc( size );
}

En dat werkt hier voor een testprogramma goed:

$ cat test.c
#include <stdio.h>
#include <stdlib.h>
int main( int argc, char **argv )
{
        malloc( 2 ); // The wrapper hooks malloc(), so we need to use it.
        printf( "Hoi!\n" ); // Print something
        *( (char *) 0 ) = 0; // And crash
}

$ ./test
Hoi!
Segmentation fault
$ ./test | cat
$ LD_PRELOAD=./unbuffer.so ./test | cat
Hoi!

Die oplossing met script heet dezelfde uitwerking: omdat stdout van arcconf een pseudo-tty is en geen pipe zal stdout line-buffered zijn in plaats van fully buffered.

[Squee]

Wow, dat is een flink smerige hack!

Helaas had ik inmiddels mijn script al aan de praat met "script", maar in ieder geval iedereen van harte bedankt die meegedacht heeft. Binnenkort kan onze server het me nu eindelijk vertellen als er wat mis gaat

[Squee]

Nog even een kleine update voor de geinteresseerden. Uiteindelijk bleek 'script' wel goed te werken in een perl script, maar alsnog alleen als het perl script dan vanaf een terminal aangeroepen werd. Zodra ik het in een cronjob zette kreeg ik geen output meer van mijn applicatie vreemdgenoeg.
Ik ga nu dan toch maar voor de dirty dynamic library hack van deadinspace

[deadinspace]

Squee schreef op maandag 22 oktober 2007 @ 21:22:
Ik ga nu dan toch maar voor de dirty dynamic library hack van deadinspace

Yaaay

Als je het te erg vindt, dan kun je met wat creativiteit ook wel zelf een script-achtig progje maken dat een pseudo-tty aanmaakt en daar arcconf op runt. Maar dat is ook een hack, alleen een iets minder enge omdat je niet run-time in het programma poked

[Squee]

deadinspace schreef op maandag 22 oktober 2007 @ 23:51:
Als je het te erg vindt, dan kun je met wat creativiteit ook wel zelf een script-achtig progje maken dat een pseudo-tty aanmaakt en daar arcconf op runt. Maar dat is ook een hack, alleen een iets minder enge omdat je niet run-time in het programma poked

Ik had ook nog even gekeken of ik het in 'screen' kon runnen, maar dat gaf ook allemaal vage problemen. Vooral de combinatie van screen en script; dat leverde een explosie van processen op vreemd genoeg

Nee ik ben wel tevreden zo, het werkt!