[syslog-ng] Problem with syslog-ng 1.6.8 and HUP - More information

Tessier.Marc.2 at hydro.qc.ca Tessier.Marc.2 at hydro.qc.ca
Tue Sep 16 15:17:41 CEST 2008


Hi,

	This is a Solaris 9 (SunOS spdmze21 5.9 Generic_122300-13 sun4u
sparc SUNW,Sun-Fire-V240), running syslog-ng 1.6.8.  After my previous
posts to the list, I managed to get 2 truss outputs, once showing the
signal being received and processed and one showing the signal being
received and nothing happening at all.  Here is what happens when the
signal isn't processed : 

/1:         Received signal #1, SIGHUP, in poll() [caught]
/1:     poll(0xFFBFEC78, 329, 100)                      Err#4 EINTR
/1:     sigprocmask(SIG_SETMASK, 0xFFBFE81C, 0x00000000) = 0
/1:     sigaction(SIGHUP, 0xFFBFE5E0, 0xFFBFE700)       = 0
/1:     sigprocmask(SIG_SETMASK, 0xFF0AA094, 0xFFBFE5D0) = 0
/1:     lwp_unpark(1, 1)                                = 0
/1:     setcontext(0xFFBFE5E0)
/1:     so_socket(PF_INET, SOCK_DGRAM, IPPROTO_IP, "", 1) = 296
/1:     ioctl(296, 0xC00C6982, 0xFFBFF6C4)              = 0
/1:     close(296)                                      = 0
/1:     sysinfo(SI_SRPC_DOMAIN, "", 256)                = 1
/1:     open("/etc/resolv.conf", O_RDONLY|O_LARGEFILE)  = 296
/1:     read(296, " ; - - - - - - - - - - -".., 1024)   = 1024
/1:     read(296, " a m e s e r v e r   1 2".., 1024)   = 515
/1:     read(296, 0x0013D638, 1024)                     = 0
/1:     close(296)                                      = 0
/1:     write(2, " S I G H U P   r e c e i".., 38)      = 38
/1:     poll(0xFFBFEC78, 329, 100)                      = 1
/1:     read(84, " < 2 2 > S e p   1 0   1".., 8192)    = 1522
/1:     poll(0xFFBFEC78, 329, 100)                      = 3
/1:     read(84, " < 2 3 > S e p   1 0   1".., 8192)    = 1661
/1:     write(210, " S e p   1 0   1 6 : 0 2".., 3091)  = 3091
/1:     write(209, " S e p   1 0   1 6 : 0 2".., 3091)  = 3091
/1:     poll(0xFFBFEC78, 329, 100)                      = 1
/1:     read(294, " < 2 2 > S e p   1 0   1".., 8192)   = 3253
/1:     poll(0xFFBFEC78, 329, 100)                      = 3
/1:     read(294, " < 2 3 > S e p   1 0   1".., 8192)   = 3284
/1:     write(16, " S e p   1 0   1 6 : 0 2".., 4096)   = 4096
/1:     write(16, " o u n d a r y = " = _ r".., 2121)   = 2121
/1:     write(15, " S e p   1 0   1 6 : 0 2".., 4096)   = 4096
/1:     write(15, " o u n d a r y = " = _ r".., 2121)   = 2121
/1:     poll(0xFFBFEC78, 329, 100)                      = 3
/1:     read(84, " < 2 2 > S e p   1 0   1".., 8192)    = 3045
/1:     read(294, " < 2 3 > S e p   1 0   1".., 8192)   = 552
/1:     read(166, " < 1 6 6 > S e p   1 0  ".., 8192)   = 312
/1:     poll(0xFFBFEC78, 329, 100)                      = 5
/1:     read(84, " < 2 2 > S e p   1 0   1".., 8192)    = 1584
/1:     write(210, " S e p   1 0   1 6 : 0 2".., 4096)  = 4096
/1:     write(210, " 5 5 3   m a i l . i n f".., 421)   = 421
/1:     write(209, " S e p   1 0   1 6 : 0 2".., 4096)  = 4096
/1:     write(209, " 5 5 3   m a i l . i n f".., 421)   = 421
/1:     write(16, " S e p   1 0   1 6 : 0 2".., 528)    = 528
/1:     write(15, " S e p   1 0   1 6 : 0 2".., 528)    = 528
/1:     poll(0xFFBFEC78, 329, 100)                      = 1
/1:     read(84, " < 2 3 > S e p   1 0   1".., 8192)    = 1533
/1:     poll(0xFFBFEC78, 329, 100)                      = 2
/1:     write(210, " S e p   1 0   1 6 : 0 2".., 1489)  = 1489
/1:     write(209, " S e p   1 0   1 6 : 0 2".., 1489)  = 1489
/1:     poll(0xFFBFEC78, 329, 100)                      = 1
/1:     read(84, " < 2 2 > S e p   1 0   1".., 8192)    = 1484
/1:     poll(0xFFBFEC78, 329, 100)                      = 2
/1:     write(210, " S e p   1 0   1 6 : 0 2".., 1444)  = 1444
/1:     write(209, " S e p   1 0   1 6 : 0 2".., 1444)  = 1444
/1:     poll(0xFFBFEC78, 329, 100)                      = 1
/1:     read(84, " < 2 3 > S e p   1 0   1".., 8192)    = 1526
/1:     poll(0xFFBFEC78, 329, 100)                      = 2
/1:     write(210, " S e p   1 0   1 6 : 0 2".., 1498)  = 1498
/1:     write(209, " S e p   1 0   1 6 : 0 2".., 1498)  = 1498
/1:     poll(0xFFBFEC78, 329, 100)                      = 1
/1:     read(84, " < 2 2 > S e p   1 0   1".., 8192)    = 1799
/1:     poll(0xFFBFEC78, 329, 100)                      = 2
/1:     write(210, " S e p   1 0   1 6 : 0 2".., 1771)  = 1771
/1:     write(209, " S e p   1 0   1 6 : 0 2".., 1771)  = 1771
/1:     poll(0xFFBFEC78, 329, 100)                      = 1
/1:     read(84, " < 2 3 > S e p   1 0   1".., 8192)    = 1643
/1:     poll(0xFFBFEC78, 329, 100)                      = 3
/1:     read(84, " < 2 2 > S e p   1 0   1".., 8192)    = 1569
/1:     write(210, " S e p   1 0   1 6 : 0 2".., 3168)  = 3168
/1:     write(209, " S e p   1 0   1 6 : 0 2".., 3168)  = 3168
/1:     poll(0xFFBFEC78, 329, 100)                      = 1
/1:     read(84, " < 2 2 > S e p   1 0   1".., 8192)    = 1814
/1:     poll(0xFFBFEC78, 329, 100)                      = 3
/1:     read(294, " < 2 3 > S e p   1 0   1".., 8192)   = 1481
/1:     write(210, " S e p   1 0   1 6 : 0 2".., 1794)  = 1794
/1:     write(209, " S e p   1 0   1 6 : 0 2".., 1794)  = 1794
/1:     poll(0xFFBFEC78, 329, 100)                      = 2
/1:     write(16, " S e p   1 0   1 6 : 0 2".., 1438)   = 1438
/1:     write(15, " S e p   1 0   1 6 : 0 2".., 1299)   = 1299
/1:     poll(0xFFBFEC78, 329, 100)                      = 1
/1:     read(84, " < 2 3 > S e p   1 0   1".., 8192)    = 1496
/1:     poll(0xFFBFEC78, 329, 100)                      = 2
/1:     write(210, " S e p   1 0   1 6 : 0 2".., 1456)  = 1456
/1:     write(209, " S e p   1 0   1 6 : 0 2".., 1456)  = 1456
/1:     poll(0xFFBFEC78, 329, 100)                      = 1
/1:     read(84, " < 2 3 > S e p   1 0   1".., 8192)    = 1537
/1:     poll(0xFFBFEC78, 329, 100)                      = 3
/1:     write(210, " S e p   1 0   1 6 : 0 2".., 1485)  = 1485
/1:     write(209, " S e p   1 0   1 6 : 0 2".., 1485)  = 1485
/1:     read(166, " < 1 6 6 > S e p   1 0  ".., 8192)   = 796
/1:     poll(0xFFBFEC78, 329, 100)                      = 2
/1:     write(37, " S e p   1 0   1 6 : 0 2".., 1088)   = 1088
/1:     write(36, " S e p   1 0   1 6 : 0 2".., 1088)   = 1088
/1:     poll(0xFFBFEC78, 329, 100)                      = 1
/1:     read(84, " < 2 2 > S e p   1 0   1".., 8192)    = 1618
/1:     poll(0xFFBFEC78, 329, 100)                      = 2
/1:     write(210, " S e p   1 0   1 6 : 0 2".., 1598)  = 1598
/1:     write(209, " S e p   1 0   1 6 : 0 2".., 1598)  = 1598
/1:     poll(0xFFBFEC78, 329, 100)                      = 1
/1:     read(84, " < 2 2 > S e p   1 0   1".., 8192)    = 1720
/1:     poll(0xFFBFEC78, 329, 100)                      = 3
/1:     read(84, " < 2 2 > S e p   1 0   1".., 8192)    = 1795
/1:     write(210, " S e p   1 0   1 6 : 0 2".., 3447)  = 3447
/1:     write(209, " S e p   1 0   1 6 : 0 2".., 3447)  = 3447
/1:     poll(0xFFBFEC78, 329, 100)                      = 1
/1:     read(84, " < 2 3 > S e p   1 0   1".., 8192)    = 1580
/1:     poll(0xFFBFEC78, 329, 100)                      = 2
/1:     write(210, " S e p   1 0   1 6 : 0 2".., 1532)  = 1532
/1:     write(209, " S e p   1 0   1 6 : 0 2".., 1532)  = 1532
/1:     poll(0xFFBFEC78, 329, 100)                      = 1
/1:     read(294, " < 2 2 > S e p   1 0   1".., 8192)   = 1155
/1:     poll(0xFFBFEC78, 329, 100)                      = 4
/1:     read(84, " < 2 3 > S e p   1 0   1".., 8192)    = 2980
/1:     write(50, " S e p   1 0   1 6 : 0 2".., 278)    = 278
/1:     write(16, " S e p   1 0   1 6 : 0 2".., 1128)   = 1128
/1:     write(15, " S e p   1 0   1 6 : 0 2".., 989)    = 989
/1:     poll(0xFFBFEC78, 329, 100)                      = 2
/1:     write(210, " S e p   1 0   1 6 : 0 2".., 2900)  = 2900
/1:     write(209, " S e p   1 0   1 6 : 0 2".., 2900)  = 2900
/1:     poll(0xFFBFEC78, 329, 100)                      = 1
/1:     read(294, " < 2 2 > S e p   1 0   1".., 8192)   = 1542
/1:     poll(0xFFBFEC78, 329, 100)                      = 2
/1:     write(16, " S e p   1 0   1 6 : 0 2".., 1510)   = 1510
/1:     write(15, " S e p   1 0   1 6 : 0 2".., 1510)   = 1510
/1:     poll(0xFFBFEC78, 329, 100)                      = 1
/1:     read(84, " < 2 3 > S e p   1 0   1".., 8192)    = 1263
/1:     poll(0xFFBFEC78, 329, 100)                      = 2
/1:     write(210, " S e p   1 0   1 6 : 0 2".., 1223)  = 1223
/1:     write(209, " S e p   1 0   1 6 : 0 2".., 1223)  = 1223
/1:     poll(0xFFBFEC78, 329, 100)                      = 1
/1:     read(84, " < 2 2 > S e p   1 0   1".., 8192)    = 1508
/1:     poll(0xFFBFEC78, 329, 100)                      = 2
/1:     write(210, " S e p   1 0   1 6 : 0 2".., 1460)  = 1460
/1:     write(209, " S e p   1 0   1 6 : 0 2".., 1460)  = 1460
/1:     poll(0xFFBFEC78, 329, 100)                      = 1
/1:     read(51, " < 1 6 6 > S e p   1 0  ".., 8192)    = 256
/1:     poll(0xFFBFEC78, 329, 100)                      = 1
/1:     read(294, " < 2 3 > S e p   1 0   1".., 8192)   = 1149
/1:     poll(0xFFBFEC78, 329, 100)                      = 2
/1:     write(16, " S e p   1 0   1 6 : 0 2".., 1117)   = 1117
/1:     write(15, " S e p   1 0   1 6 : 0 2".., 1117)   = 1117
/1:     poll(0xFFBFEC78, 329, 100)                      = 1
/1:     read(294, " < 2 2 > S e p   1 0   1".., 8192)   = 1541
/1:     poll(0xFFBFEC78, 329, 100)                      = 3
/1:     read(84, " < 2 3 > S e p   1 0   1".., 8192)    = 1496
/1:     write(16, " S e p   1 0   1 6 : 0 2".., 1493)   = 1493
/1:     write(15, " S e p   1 0   1 6 : 0 2".., 1493)   = 1493
/1:     poll(0xFFBFEC78, 329, 100)                      = 2
/1:     write(210, " S e p   1 0   1 6 : 0 2".., 1452)  = 1452
/1:     write(209, " S e p   1 0   1 6 : 0 2".., 1452)  = 1452
/1:     poll(0xFFBFEC78, 329, 100)                      = 1
/1:     read(294, " < 2 3 > S e p   1 0   1".., 8192)   = 1488
/1:     poll(0xFFBFEC78, 329, 100)                      = 2
/1:     write(16, " S e p   1 0   1 6 : 0 2".., 1436)   = 1436
/1:     write(15, " S e p   1 0   1 6 : 0 2".., 1436)   = 1436
/1:     poll(0xFFBFEC78, 329, 100)                      = 1
/1:     read(51, " < 1 6 6 > S e p   1 0  ".., 8192)    = 504
/1:     poll(0xFFBFEC78, 329, 100)                      = 2
/1:     write(57, " S e p   1 0   1 6 : 0 1".., 745)    = 745
/1:     write(56, " S e p   1 0   1 6 : 0 1".., 745)    = 745
/1:     poll(0xFFBFEC78, 329, 100)                      = 1
/1:     read(84, " < 2 3 > S e p   1 0   1".., 8192)    = 1592
/1:     poll(0xFFBFEC78, 329, 100)                      = 2
/1:     write(210, " S e p   1 0   1 6 : 0 2".., 1556)  = 1556
/1:     write(209, " S e p   1 0   1 6 : 0 2".., 1556)  = 1556
/1:     poll(0xFFBFEC78, 329, 100)                      = 1
/1:     read(242, " < 2 2 > S e p   1 0   1".., 8192)   = 125
/1:     poll(0xFFBFEC78, 329, 100)                      = 1
/1:     read(294, " < 2 2 > S e p   1 0   1".., 8192)   = 938
/1:     poll(0xFFBFEC78, 329, 100)                      = 2

	It continues on and on with reads, writes and polls as if the
signal was never received at all (though it did catch it).  When it does
work, you see that it opens its config file and starts to close FD (I
cut it after a couple of closes, there are 3 dozens since this server is
a central logging server) : 

/1:         Received signal #1, SIGHUP, in poll() [caught]
/1:     poll(0xFFBFEC58, 333, 100)                      Err#4 EINTR
/1:     sigprocmask(SIG_SETMASK, 0xFFBFE7FC, 0x00000000) = 0
/1:     sigaction(SIGHUP, 0xFFBFE5C0, 0xFFBFE6E0)       = 0
/1:     sigprocmask(SIG_SETMASK, 0xFF0AA094, 0xFFBFE5B0) = 0
/1:     lwp_unpark(1, 1)                                = 0
/1:     setcontext(0xFFBFE5C0)
/1:     so_socket(PF_INET, SOCK_DGRAM, IPPROTO_IP, "", 1) = 77
/1:     ioctl(77, 0xC00C6982, 0xFFBFF6C4)               = 0
/1:     close(77)                                       = 0
/1:     sysinfo(SI_SRPC_DOMAIN, "", 256)                = 1
/1:     open("/etc/resolv.conf", O_RDONLY|O_LARGEFILE)  = 77
/1:     fcntl(77, F_DUPFD, 0x00000100)                  = 315
/1:     close(77)                                       = 0
/1:     read(315, " ; - - - - - - - - - - -".., 1024)   = 1024
/1:     read(315, " a m e s e r v e r   1 2".., 1024)   = 515
/1:     read(315, 0x0009B5E0, 1024)                     = 0
/1:     close(315)                                      = 0
/1:     write(2, " S I G H U P   r e c e i".., 38)      = 38
/1:     poll(0xFFBFEC58, 333, 100)                      = 1
/1:     read(192, " < 1 6 6 > S e p   1 0  ".., 8192)   = 243
/1:     poll(0xFFBFEC58, 333, 100)                      = 1
/1:     read(84, " < 2 2 > S e p   1 0   1".., 8192)    = 1761
/1:     poll(0xFFBFEC58, 333, 100)                      = 4
/1:     read(84, " < 2 3 > S e p   1 0   1".., 8192)    = 1481
/1:     read(54, " < 1 6 6 > S e p   1 0  ".., 8192)    = 1257
/1:     write(55, " S e p   1 0   1 5 : 0 6".., 3142)   = 3142
/1:     write(53, " S e p   1 0   1 5 : 0 6".., 3142)   = 3142
/1:     poll(0xFFBFEC58, 333, 100)                      = 4
/1:     read(84, " < 2 3 > S e p   1 0   1".., 8192)    = 1742
/1:     read(264, " < 1 6 6 > S e p   1 0  ".., 8192)   = 357
/1:     write(143, " S e p   1 0   1 5 : 1 1".., 1568)  = 1568
/1:     write(142, " S e p   1 0   1 5 : 1 1".., 1568)  = 1568
/1:     poll(0xFFBFEC58, 333, 100)                      = 2
/1:     write(55, " S e p   1 0   1 5 : 0 6".., 1694)   = 1694
/1:     write(53, " S e p   1 0   1 5 : 0 6".., 1694)   = 1694
/1:     poll(0xFFBFEC58, 333, 100)                      = 1
/1:     read(250, " < 2 3 > S e p   1 0   1".., 8192)   = 88
/1:     poll(0xFFBFEC58, 333, 100)                      = 1
/1:     read(264, " < 2 2 > S e p   1 0   1".., 8192)   = 1463
/1:     poll(0xFFBFEC58, 333, 100)                      = 3
/1:     read(84, " < 2 3 > S e p   1 0   1".., 8192)    = 1574
/1:     write(23, " S e p   1 0   1 5 : 0 6".., 1419)   = 1419
/1:     write(18, " S e p   1 0   1 5 : 0 6".., 1771)   = 1771
/1:     poll(0xFFBFEC58, 333, 100)                      = 2
/1:     write(55, " S e p   1 0   1 5 : 0 6".., 1526)   = 1526
/1:     write(53, " S e p   1 0   1 5 : 0 6".., 1526)   = 1526
/1:     poll(0xFFBFEC58, 333, 100)                      = 1
/1:     read(84, " < 2 2 > S e p   1 0   1".., 8192)    = 1809
/1:     poll(0xFFBFEC58, 333, 100)                      = 2
/1:     write(53, " S e p   1 0   1 5 : 0 6".., 1780)   = 1780
/1:     write(52, " S e p   1 0   1 5 : 0 6".., 1692)   = 1692
/1:     poll(0xFFBFEC58, 333, 100)                      = 1
/1:     read(192, " < 1 6 6 > S e p   1 0  ".., 8192)   = 478
/1:     poll(0xFFBFEC58, 333, 100)                      = 2
/1:     write(71, " S e p   1 0   1 5 : 0 6".., 706)    = 706
/1:     write(69, " S e p   1 0   1 5 : 0 6".., 706)    = 706
/1:     poll(0xFFBFEC58, 333, 100)                      = 1
/1:     read(84, " < 2 2 > S e p   1 0   1".., 8192)    = 1549
/1:     poll(0xFFBFEC58, 333, 100)                      = 2
/1:     write(55, " S e p   1 0   1 5 : 0 6".., 1589)   = 1589
/1:     write(53, " S e p   1 0   1 5 : 0 6".., 1501)   = 1501
/1:     poll(0xFFBFEC58, 333, 100)                      = 1
/1:     read(120, " < 1 6 6 > S e p   1 0  ".., 8192)   = 325
/1:     poll(0xFFBFEC58, 333, 100)                      = 1
/1:     read(250, " < 2 2 > S e p   1 0   1".., 8192)   = 137
/1:     open("/etc/syslog-ng.conf", O_RDONLY)           = 77
/1:     ioctl(77, TCGETA, 0xFFBFF53C)                   Err#25 ENOTTY
/1:     fstat64(77, 0xFFBFEF20)                         = 0
/1:     fstat64(77, 0xFFBFEDC8)                         = 0
/1:     ioctl(77, TCGETA, 0xFFBFEEAC)                   Err#25 ENOTTY
/1:     read(77, " # - - - - - - - - - - -".., 8192)    = 7404
/1:     read(77, 0x0006AB94, 8192)                      = 0
/1:     door_info(6, 0xFFBFEC20)                        = 0
/1:     door_call(6, 0xFFBFEC08)                        = 0
/1:     door_info(6, 0xFFBFD020)                        = 0
/1:     door_call(6, 0xFFBFD008)                        = 0
/1:     door_info(6, 0xFFBFEC20)                        = 0
/1:     door_call(6, 0xFFBFEC08)                        = 0
/1:     door_info(6, 0xFFBFD020)                        = 0
/1:     door_call(6, 0xFFBFD008)                        = 0
/1:     ioctl(77, TCGETA, 0xFFBFEFA4)                   Err#25 ENOTTY
/1:     llseek(77, 0, SEEK_CUR)                         = 7404
/1:     close(77)                                       = 0
/1:     poll(0xFFBFF6C8, 0, 0)                          = 0
/1:     door_revoke(13)                                 = 0
/1:     close(13)                                       Err#9 EBADF
/1:     close(59)                                       = 0
/1:     close(344)                                      = 0
/1:     close(316)                                      = 0

	I guess there's something in there that indicates what the
problem is exactly, but I'm not qualified enough in system call tracing
to say what it could be.

	Maybe one of you guys has an idea ? 
 
Thank you for any help!
 
Marc Tessier
Analyste Support Technique
Support Technique des Infrastructures 
courriel : tessier.marc.2 at hydro.qc.ca
<mailto:tessier.marc.2 at hydro.qc.ca> 
Tel:  (514) 840-3000 Poste #6467



More information about the syslog-ng mailing list