Issue with the Bot file output

[Th4nat0s]

I got a really strange issue with the last beta 1. I had linked the parser to the deduplicator then to file output

The bot don't start...

# ./intelmqctl --bot status --id file-output                                                                                                  
file-output is stopped.
# ./intelmqctl --bot start --id file-output                                                                                                   
Starting file-output...
file-output is already running.
# ./intelmqctl --bot status --id file-output                                                                                                  
file-output is stopped.

It didn't generate any logs.. BUT ...Manually... seems Ok.. no error, and no output

# python -m intelmq.bots.outputs.file.output file-output

The logs then start... but it do "nothing"...

2015-06-07 02:48:42,995 - file-output - INFO - Bot is starting
2015-06-07 02:48:42,995 - file-output - DEBUG - Defaults configuration from '/opt/intelmq/etc/defaults.conf' file
2015-06-07 02:48:42,995 - file-output - DEBUG - Defaults configuration: parameter 'destination_pipeline_host' loaded with value '127.0.0.1'
2015-06-07 02:48:42,995 - file-output - DEBUG - Defaults configuration: parameter 'error_max_retries' loaded with value '3'
2015-06-07 02:48:42,995 - file-output - DEBUG - Defaults configuration: parameter 'destination_pipeline_port' loaded with value '6379'
2015-06-07 02:48:42,996 - file-output - DEBUG - Defaults configuration: parameter 'destination_pipeline_db' loaded with value '2'
2015-06-07 02:48:42,996 - file-output - DEBUG - Defaults configuration: parameter 'rate_limit' loaded with value '0'
2015-06-07 02:48:42,996 - file-output - DEBUG - Defaults configuration: parameter 'error_log_exception' loaded with value 'True'
2015-06-07 02:48:42,996 - file-output - DEBUG - Defaults configuration: parameter 'broker' loaded with value 'redis'
2015-06-07 02:48:42,996 - file-output - DEBUG - Defaults configuration: parameter 'error_procedure' loaded with value 'retry'
2015-06-07 02:48:42,996 - file-output - DEBUG - Defaults configuration: parameter 'error_retry_delay' loaded with value '15'
2015-06-07 02:48:42,996 - file-output - DEBUG - Defaults configuration: parameter 'source_pipeline_host' loaded with value '127.0.0.1'
2015-06-07 02:48:42,996 - file-output - DEBUG - Defaults configuration: parameter 'source_pipeline_db' loaded with value '2'
2015-06-07 02:48:42,996 - file-output - DEBUG - Defaults configuration: parameter 'error_dump_message' loaded with value 'True'
2015-06-07 02:48:42,996 - file-output - DEBUG - Defaults configuration: parameter 'source_pipeline_port' loaded with value '6379'
2015-06-07 02:48:42,996 - file-output - DEBUG - Defaults configuration: parameter 'error_log_message' loaded with value 'True'
2015-06-07 02:48:42,996 - file-output - DEBUG - Defaults configuration: parameter 'load_balance' loaded with value 'True'
2015-06-07 02:48:42,996 - file-output - DEBUG - Runtime configuration: loading 'file-output' section from '/opt/intelmq/etc/runtime.conf' file
2015-06-07 02:48:42,996 - file-output - DEBUG - Runtime configuration: parameter 'error_retry_delay' loaded with value '30'
2015-06-07 02:48:42,996 - file-output - DEBUG - Runtime configuration: parameter 'error_log_message' loaded with value 'True'
2015-06-07 02:48:42,996 - file-output - DEBUG - Runtime configuration: parameter 'error_dump_message' loaded with value 'True'
2015-06-07 02:48:42,996 - file-output - DEBUG - Runtime configuration: parameter 'file' loaded with value '/opt/intelmq/var/lib/bots/file-output/events.txt'
2015-06-07 02:48:42,996 - file-output - DEBUG - Runtime configuration: parameter 'error_procedure' loaded with value 'retry'
2015-06-07 02:48:42,997 - file-output - DEBUG - Pipeline configuration: loading 'file-output' section from '/opt/intelmq/etc/pipeline.conf' file
2015-06-07 02:48:42,997 - file-output - DEBUG - Pipeline configuration: parameter 'source-queue' loaded with the value 'file-output-queue'
2015-06-07 02:48:42,997 - file-output - DEBUG - Harmonization configuration: loading all '/opt/intelmq/etc/harmonization.conf' file
2015-06-07 02:48:42,997 - file-output - DEBUG - Opening /opt/intelmq/var/lib/bots/file-output/events.txt file
2015-06-07 02:48:42,997 - file-output - INFO - File /opt/intelmq/var/lib/bots/file-output/events.txt is open.
2015-06-07 02:48:42,997 - file-output - INFO - Bot start processing
2015-06-07 02:48:42,997 - file-output - INFO - Loading source pipeline
2015-06-07 02:48:42,997 - file-output - INFO - Loading source queue
2015-06-07 02:48:42,997 - file-output - INFO - Source queue loaded
2015-06-07 02:48:42,997 - file-output - INFO - Connected to source queue
2015-06-07 02:48:42,998 - file-output - INFO - Loading destination queues
2015-06-07 02:48:42,998 - file-output - INFO - Destination queues loaded
2015-06-07 02:48:42,998 - file-output - INFO - Connected to destination queues
2015-06-07 02:48:42,998 - file-output - INFO - Pipeline ready
2015-06-07 02:48:42,998 - file-output - INFO - Start processing

More fun, the queue seems all emptys.

# ./intelmqctl  --list queues
arbor-parser-queue - 0
deduplicator-expert-queue - 0
feodo-raw-ip-parser-queue - 0
file-output-queue - 0
malware-domain-list-parser-queue - 0
palevo-raw-ip-parser-queue - 0
phishtank-parser-queue - 0
zeus-raw-ip-parser-queue - 0

But they do have events... (my custom parser sees them and had processed)

2015-06-07 02:51:57,424 - zeus-raw-ip-parser - DEBUG - Will apply regex ^\s*(?P<ip>(?:(?:\d){1,3}\.){3}\d{1,3})
2015-06-07 02:51:57,609 - zeus-raw-ip-parser - INFO - Processed 202 event

Any Hint for debugging that ?... I have no more ideas

[SYNchroACK]

Well..more things to check:

1. remember that deduplicator can be removing duplicated events
2. when you run a bot manually as a root sometimes log files etc are created as root and then when you use the usual way to start, the bot will fail....

feedback?

[Th4nat0s]

Well, I'ts my dev machine, I flush reddis before test ; 

redis-cli FLUSHALL
redis-cli FLUSHDB

So deduplicator is "fresh".. then I also, at every install, launch a

chmod -R 0770 /opt/intelmq
chown -R intelmq.intelmq /opt/intelmq

I have the same issue with the cymru plugin (with import fixed). and abusix expert...

# python -m intelmq.bots.experts.cymru_whois.expert cymru-expert

I could not start "alone"... but start with python... Still can't understand what append

[SYNchroACK]

I found the problem. BOTS file which is being use by manager hás bugs... Reason, when i renamed the files like experts, i forgot to update BOTS file. I send a commit to fix it. Sorry

[SYNchroACK]

I hope this commit will solve the issue: 4cf85c42454ff3b401aefb3899c3de37e9e4baf5

Feedback?

[Th4nat0s]

Yes it was that... I think it miss a logfile for the stuff around the bots :)... Anyway, it fix a lot thanks.

May we close ?

[SYNchroACK]

can you explain "I think it miss a logfile for the stuff around the bots" ? May be we can improve it...

[Th4nat0s]

Well in this scenario where startup.conf is broken they're is no log telling it "try to start xxxx" etc.

[SYNchroACK]

hum... i think it will be difficult to have a good solution without too much complexity... but please, send a proposal, i think it will be really useful. ;)

[sebix]

intelmqctl now logs it's activities in the referenced commits.

Exception handling and logging by the Bot class is still missing.

[sebix]

Exceptions on startup (__init__) are now logged if possible, otherwise printed to stdout. I think the issue can be closed now.

[SYNchroACK]

;)