Open AS Communication Gateway

Rtlogd is broken in current trunk

Bug #1397334 reported by X1D32G2pEQ on 2014-11-28

This bug affects 1 person

Affects		Status	Importance	Assigned to	Milestone
	Open AS Communication Gateway	In Progress	Critical	stiV

Bug Description

root@mx:/var/log# /usr/bin/rtlogd
String found where operator expected at /usr/lib/perl5/Underground8/Log/Listener/Email.pm line 555, near "sysrtlog "RELAYED""
(Do you need to predeclare sysrtlog?)
String found where operator expected at /usr/lib/perl5/Underground8/Log/Listener/Email.pm line 562, near "sysrtlog "ACCEPTED""
(Do you need to predeclare sysrtlog?)
String found where operator expected at /usr/lib/perl5/Underground8/Log/Listener/Email.pm line 569, near "sysrtlog "GREYLISTED""
(Do you need to predeclare sysrtlog?)
String found where operator expected at /usr/lib/perl5/Underground8/Log/Listener/Email.pm line 576, near "sysrtlog "BLACKLISTED""
(Do you need to predeclare sysrtlog?)
String found where operator expected at /usr/lib/perl5/Underground8/Log/Listener/Email.pm line 583, near "sysrtlog "VIRUS_INFECTED""
(Do you need to predeclare sysrtlog?)
String found where operator expected at /usr/lib/perl5/Underground8/Log/Listener/Email.pm line 590, near "sysrtlog "BANNED_ATTACHMENT""
(Do you need to predeclare sysrtlog?)
syntax error at /usr/lib/perl5/Underground8/Log/Listener/Email.pm line 60, near "$self "
Global symbol "$self" requires explicit package name at /usr/lib/perl5/Underground8/Log/Listener/Email.pm line 60.
Global symbol "$self" requires explicit package name at /usr/lib/perl5/Underground8/Log/Listener/Email.pm line 60.
Global symbol "$self" requires explicit package name at /usr/lib/perl5/Underground8/Log/Listener/Email.pm line 61.
syntax error at /usr/lib/perl5/Underground8/Log/Listener/Email.pm line 555, near "sysrtlog "RELAYED""
syntax error at /usr/lib/perl5/Underground8/Log/Listener/Email.pm line 562, near "sysrtlog "ACCEPTED""
syntax error at /usr/lib/perl5/Underground8/Log/Listener/Email.pm line 569, near "sysrtlog "GREYLISTED""
syntax error at /usr/lib/perl5/Underground8/Log/Listener/Email.pm line 576, near "sysrtlog "BLACKLISTED""
syntax error at /usr/lib/perl5/Underground8/Log/Listener/Email.pm line 583, near "sysrtlog "VIRUS_INFECTED""
syntax error at /usr/lib/perl5/Underground8/Log/Listener/Email.pm line 590, near "sysrtlog "BANNED_ATTACHMENT""
/usr/lib/perl5/Underground8/Log/Listener/Email.pm has too many errors.
Compilation failed in require at /usr/bin/rtlogd line 45.
BEGIN failed--compilation aborted at /usr/bin/rtlogd line 45.

X1D32G2pEQ (x1d32g2peq-deactivatedaccount) on 2014-11-28

Changed in open-as-cgw:
importance:	Undecided → Critical
assignee:	nobody → Dominic Schallert (dschallert)
milestone:	none → 2.1.0s

X1D32G2pEQ (x1d32g2peq-deactivatedaccount) on 2014-11-28

Changed in open-as-cgw:
status:	New → Fix Released
status:	Fix Released → Fix Committed

Revision history for this message

X1D32G2pEQ (x1d32g2peq-deactivatedaccount) wrote on 2014-11-29:

rtlog is now running but still not logging to MySQL.. investigating...

root@mx:~# /etc/init.d/openas-rtlogd status
Status Open AS rtlogd is: (running).

root@mx:~# ps aux | grep rtlog
root 15647 0.0 0.3 64012 4048 ? S 16:32 0:00 openas-rtlogd-listener
root 15648 0.0 0.0 4444 648 ? S 16:32 0:00 sh -c logger -t 'openas-rtlogd-listener[15647]'
root 15649 0.0 0.0 7448 612 ? S 16:32 0:00 logger -t openas-rtlogd-listener[15647]
root 16620 0.0 0.8 152472 8928 ? S 16:42 0:00 openas-rtlogd-writer
root 16621 0.0 0.0 4444 644 ? S 16:42 0:00 sh -c logger -t 'openas-rtlogd-writer[16620]'
root 16622 0.0 0.0 7448 616 ? S 16:42 0:00 logger -t openas-rtlogd-writer[16620]
root 16629 0.0 0.0 12000 900 pts/1 S+ 16:44 0:00 grep --color=auto rtlog
root 20275 0.0 0.2 64012 3012 ? Ss 13:32 0:00 openas-rtlogd
root 20276 0.0 0.0 4444 196 ? S 13:32 0:00 sh -c logger -t 'openas-rtlogd[20275]'
root 20277 0.0 0.0 7448 140 ? S 13:32 0:00 logger -t openas-rtlogd[20275]

Revision history for this message

X1D32G2pEQ (x1d32g2peq-deactivatedaccount) wrote on 2014-11-29:

root@mx:~# /usr/bin/rtlogd.pl -debug 9 -console

11/29/14 16:56:00 openas-rtlogd: Debugging ist turned on (9)
11/29/14 16:56:00 openas-rtlogd-listener[18441]: started listener process
11/29/14 16:56:00 openas-rtlogd: activating alarm and going to sleep
11/29/14 16:56:00 openas-rtlogd-writer[18442]: started writer process
11/29/14 16:56:00 rtlog-mysql: starting up
11/29/14 16:56:00 rtlog-mysql: Connected to MySQL database
11/29/14 16:56:00 rtlog-mysql: Preparing Statements
11/29/14 16:56:08 rtlog-listener: postfix/qmgr : 19D43121854: from=<email address hidden>, size=34950, nrcpt=1 (queue active)
11/29/14 16:56:08 rtlog-listener: not initalized: message from postfix/qmgr
11/29/14 16:56:08 rtlog-listener: postfix/smtpd : connect from localhost[127.0.0.1]
11/29/14 16:56:08 rtlog-listener: postfix/smtpd : 7B033121866: client=localhost[127.0.0.1]
11/29/14 16:56:08 rtlog-listener: postfix/qmgr : 7B033121866: from=<email address hidden>, size=1309, nrcpt=1 (queue active)

Revision history for this message

X1D32G2pEQ (x1d32g2peq-deactivatedaccount) wrote on 2014-11-29:

root@mx:~# cat < /var/limes/rt_log

2014-11-29T17:04:55+01:00 mx postfwd2/policy[21205]: [CACHE] rule=1, id=DUMMY, client=web.heise.de[193.99.144.71], sender=<email address hidden>, recipient=<email address hidden>, helo=<web.heise.de>, proto=ESMTP, state=RCPT, delay=0.00s, hits=DUMMY, action=DUNNO
2014-11-29T17:04:55+01:00 mx postfix/smtpd[19108]: connect from localhost[127.0.0.1]
2014-11-29T17:05:04+01:00 mx postfwd2/policy[21205]: [CACHE] rule=1, id=DUMMY, client=web.heise.de[193.99.144.71], sender=<email address hidden>, recipient=<email address hidden>, helo=<web.heise.de>, proto=ESMTP, state=RCPT, delay=0.00s, hits=DUMMY, action=DUNNO
2014-11-29T17:05:05+01:00 mx postfix/smtpd[19108]: connect from localhost[127.0.0.1]
2014-11-29T17:05:05+01:00 mx postfix/qmgr[14685]: B4043121866: from=<email address hidden>, size=2951, nrcpt=1 (queue active)
2014-11-29T17:05:05+01:00 mx postfix/smtpd[19108]: disconnect from localhost[127.0.0.1]

Revision history for this message

X1D32G2pEQ (x1d32g2peq-deactivatedaccount) wrote on 2014-12-09:

former POLICYD regex's have to be adjusted for SQLGrey:

NEW MAIL:
------------------------------------------------
2014-12-09T02:19:44+01:00 mx sqlgrey: grey: new: 193.99.144.71(193.99.144.71), <email address hidden> -> <email address hidden>

RECONNECT (TOO FAST):
------------------------------------------------
2014-12-09T02:20:14+01:00 mx sqlgrey: grey: early reconnect: 193.99.144.71(193.99.144.71), <email address hidden> -> <email address hidden>

RECONNECT (AFTER 5MIN):
------------------------------------------------
2014-12-09T02:28:01+01:00 mx sqlgrey: grey: reconnect ok: 193.99.144.71(193.99.144.71), <email address hidden> -> <email address hidden> (00:08:17)

RECONNECT (SELECTIVE/AWL):
------------------------------------------------
2014-12-09T02:28:01+01:00 mx sqlgrey: grey: from awl: 193.99.144.71, <email address hidden> added

X1D32G2pEQ (x1d32g2peq-deactivatedaccount) on 2014-12-09

Changed in open-as-cgw:
status:	Fix Committed → In Progress
assignee:	Dominic Schallert (dschallert) → stiV (stefan-wehinger)

Revision history for this message

X1D32G2pEQ (x1d32g2peq-deactivatedaccount) wrote on 2014-12-10:

domain awl match: updating
from awl match: updating
from auto-whitelisted by
early reconnect:
reconnect ok:
domain awl:
from awl:
new:
delayed
throttling:

Revision history for this message

X1D32G2pEQ (x1d32g2peq-deactivatedaccount) wrote on 2015-10-27:

Download full text (3.9 KiB)

Issue still exists in current rev. 135.

Rtlogd now receives the email object, but data is not written to the DB... Investigating.

[root@mx:/etc/syslog-ng] $ /usr/bin/rtlogd.pl -debug 9 -console
10/27/15 04:41:10 openas-rtlogd: Debugging ist turned on (9)
10/27/15 04:41:10 openas-rtlogd-listener[32591]: started listener process
10/27/15 04:41:10 openas-rtlogd: activating alarm and going to sleep
10/27/15 04:41:10 openas-rtlogd-writer[32592]: started writer process
10/27/15 04:41:10 rtlog-mysql: starting up
10/27/15 04:41:10 rtlog-mysql: Connected to MySQL database
10/27/15 04:41:10 rtlog-mysql: Preparing Statements
10/27/15 04:41:23 rtlog-listener: postfix/smtpd : connect from byteplant.com[78.47.119.33]
10/27/15 04:41:23 rtlog-listener: postfix/smtpd : 52067100278: client=byteplant.com[78.47.119.33]
10/27/15 04:41:23 rtlog-listener: IP to Queue-nr: 78.47.119.33 -> 52067100278 without any mails yet.
10/27/15 04:41:23 rtlog-listener: postfix/cleanup : 52067100278: message-id=<email address hidden>
10/27/15 04:41:23 rtlog-listener: not initalized: message from postfix/cleanup
10/27/15 04:41:23 rtlog-listener: postfix/cleanup : 52067100278: warning: header Subject: Email Security Check: Please confirm your registration from byteplant.com[78.47.119.33]; from=<email address hidden> to=<email address hidden> proto=ESMTP helo=<byteplant.com>
10/27/15 04:41:23 rtlog-listener: not initalized: message from postfix/cleanup
10/27/15 04:41:23 rtlog-listener: postfix/qmgr : 52067100278: from=<email address hidden>, size=7880, nrcpt=1 (queue active)
10/27/15 04:41:23 rtlog-listener: not initalized: message from postfix/qmgr
10/27/15 04:41:23 rtlog-listener: postfix/smtpd : disconnect from byteplant.com[78.47.119.33]
10/27/15 04:41:23 rtlog-listener: postfix/smtpd : connect from localhost[127.0.0.1]
10/27/15 04:41:23 rtlog-listener: postfix/smtpd : C486D10099A: client=localhost[127.0.0.1]
10/27/15 04:41:23 rtlog-listener: postfix/cleanup : C486D10099A: message-id=<email address hidden>
10/27/15 04:41:23 rtlog-listener: not initalized: message from postfix/cleanup
10/27/15 04:41:23 rtlog-listener: postfix/qmgr : C486D10099A: from=<email address hidden>, size=8549, nrcpt=1 (queue active)
10/27/15 04:41:23 rtlog-listener: not initalized: message from postfix/qmgr
10/27/15 04:41:23 rtlog-listener: postfix/smtpd : disconnect from localhost[127.0.0.1]
10/27/15 04:41:23 rtlog-listener: amavis : (18926-08) Passed CLEAN {RelayedInbound}, DEFAULT [78.47.119.33]:43953 [78.47.119.33] <email address hidden> -> <email address hidden>, Queue-ID: 52067100278, Message-ID: <email address hidden>, mail_id: euDA8hNc2qjC, Hits: 0, size: 7885, queued_as: C486D10099A, 469 ms
10/27/15 04:41:23 rtlog-listener: not initalized: message from amavis
10/27/15 04:41:23 rtlog-listener: postfix/smtp : 52067100278: to=<email address hidden>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.58, delays=0.1/0.01/0/0.47, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as C486D10099A)
10/27/15 04:41:23 rtlog-listene...

Issue still exists in current rev. 135.

Rtlogd now receives the email object, but data is not written to the DB...  Investigating.

[root@mx:/etc/syslog-ng] $ /usr/bin/rtlogd.pl -debug 9 -console
10/27/15 04:41:10 openas-rtlogd: Debugging ist turned on (9)
10/27/15 04:41:10 openas-rtlogd-listener[32591]: started listener process
10/27/15 04:41:10 openas-rtlogd: activating alarm and going to sleep
10/27/15 04:41:10 openas-rtlogd-writer[32592]: started writer process
10/27/15 04:41:10 rtlog-mysql: starting up
10/27/15 04:41:10 rtlog-mysql: Connected to MySQL database
10/27/15 04:41:10 rtlog-mysql: Preparing Statements
10/27/15 04:41:23 rtlog-listener: postfix/smtpd : connect from byteplant.com[78.47.119.33]
10/27/15 04:41:23 rtlog-listener: postfix/smtpd : 52067100278: client=byteplant.com[78.47.119.33]
10/27/15 04:41:23 rtlog-listener: IP to Queue-nr: 78.47.119.33 -> 52067100278 without any mails yet.
10/27/15 04:41:23 rtlog-listener: postfix/cleanup : 52067100278: message-id=<1445917282.562ef2629f789@www.emailsecuritycheck.net>
10/27/15 04:41:23 rtlog-listener: not initalized: message from postfix/cleanup
10/27/15 04:41:23 rtlog-listener: postfix/cleanup : 52067100278: warning: header Subject: Email Security Check: Please confirm your registration from byteplant.com[78.47.119.33]; from=<securitycheck@emailsecuritycheck.net> to=<hello@spam-me.org> proto=ESMTP helo=<byteplant.com>
10/27/15 04:41:23 rtlog-listener: not initalized: message from postfix/cleanup
10/27/15 04:41:23 rtlog-listener: postfix/qmgr : 52067100278: from=<securitycheck@emailsecuritycheck.net>, size=7880, nrcpt=1 (queue active)
10/27/15 04:41:23 rtlog-listener: not initalized: message from postfix/qmgr
10/27/15 04:41:23 rtlog-listener: postfix/smtpd : disconnect from byteplant.com[78.47.119.33]
10/27/15 04:41:23 rtlog-listener: postfix/smtpd : connect from localhost[127.0.0.1]
10/27/15 04:41:23 rtlog-listener: postfix/smtpd : C486D10099A: client=localhost[127.0.0.1]
10/27/15 04:41:23 rtlog-listener: postfix/cleanup : C486D10099A: message-id=<1445917282.562ef2629f789@www.emailsecuritycheck.net>
10/27/15 04:41:23 rtlog-listener: not initalized: message from postfix/cleanup
10/27/15 04:41:23 rtlog-listener: postfix/qmgr : C486D10099A: from=<securitycheck@emailsecuritycheck.net>, size=8549, nrcpt=1 (queue active)
10/27/15 04:41:23 rtlog-listener: not initalized: message from postfix/qmgr
10/27/15 04:41:23 rtlog-listener: postfix/smtpd : disconnect from localhost[127.0.0.1]
10/27/15 04:41:23 rtlog-listener: amavis : (18926-08) Passed CLEAN {RelayedInbound}, DEFAULT [78.47.119.33]:43953 [78.47.119.33] <securitycheck@emailsecuritycheck.net> -> <hello@spam-me.org>, Queue-ID: 52067100278, Message-ID: <1445917282.562ef2629f789@www.emailsecuritycheck.net>, mail_id: euDA8hNc2qjC, Hits: 0, size: 7885, queued_as: C486D10099A, 469 ms
10/27/15 04:41:23 rtlog-listener: not initalized: message from amavis
10/27/15 04:41:23 rtlog-listener: postfix/smtp : 52067100278: to=<hello@spam-me.org>, relay=127.0.0.1[127.0.0.1]:10024, delay=0.58, delays=0.1/0.01/0/0.47, dsn=2.0.0, status=sent (250 2.0.0 from MTA(smtp:[127.0.0.1]:10025): 250 2.0.0 Ok: queued as C486D10099A)
10/27/15 04:41:23 rtlog-listener: postfix/qmgr : 52067100278: removed
10/27/15 04:41:23 rtlog-listener: not initalized: message from postfix/qmgr
10/27/15 04:41:23 rtlog-listener: postfix/smtp : C486D10099A: to=<hello@spam-me.org>, relay=10.0.0.6[10.0.0.6]:25, delay=0.03, delays=0/0/0.01/0.01, dsn=2.0.0, status=sent (250 2.0.0 Ok: queued as 294374871EA)
10/27/15 04:41:23 rtlog-listener: Got smtp outgoing message: C486D10099A -> hello@spam-me.org, 10.0.0.6[10.0.0.6]:25 says sent (250 2.0.0 Ok: queued as 294374871EA)
10/27/15 04:41:23 rtlog-listener: **commit_relayed 
10/27/15 04:41:23 rtlog-mysql: Received object from message queue
10/27/15 04:41:23 rtlog-mysql: Received mail object 20
10/27/15 04:41:23 rtlog-listener: postfix/qmgr : C486D10099A: removed
10/27/15 04:41:23 rtlog-listener: not initalized: message from postfix/qmgr

Revision history for this message

X1D32G2pEQ (x1d32g2peq-deactivatedaccount) wrote on 2015-10-27:

Sqlgrey bug:
---

2015-10-27T04:50:19+01:00 mx 114: warning: Use of uninitialized value $DBI::errstr in concatenation (.) or string at /usr/sbin/sqlgrey line 1493.
2015-10-27T04:50:19+01:00 mx 114: dbaccess: error: couldn't access connect table:
2015-10-27T04:50:19+01:00 mx 114: grey: get_reconnect_delay error: no connect in database for <email address hidden>, 78.47.119.33, <email address hidden>
2015-10-27T04:50:19+01:00 mx 114: warning: Use of uninitialized value $delay in concatenation (.) or string at /usr/sbin/sqlgrey line 2411.
2015-10-27T04:50:19+01:00 mx 114: grey: reconnect ok: 78.47.119.33(78.47.119.33), <email address hidden> -> <email address hidden> ()
2015-10-27T04:50:19+01:00 mx 114: grey: from awl: 78.47.119.33, <email address hidden> added

Report a bug

This report contains Public information

Everyone can see this information.

You are

Subscribing...

Edit bug mail

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.