Debugging does not present full traceback of a Python Script

[zohairajmal]

Check CONTRIBUTING guideline first and here is the list to help us investigate the problem.

Describe the bug
I am using Fluentd as superuser 'su' on my virtual machine. Whenever I try to run my python script using @type exec, it will show on the terminal as #0 plugin_helper/child_process.rb:255:child_process_execute_once: Executing command title=:exec_input spawn=[{}, "python /home/zohair/Desktop/script1.py"] mode=[:read] stderr=:discard meaning its executing the script. I also used -vv to get more information why the actions from the script were not being completed (Which were to create a folder and download some files from a webserver). The actual problem was that my python script as superuser did not have module 'requests' installed. While debugging and printing output to @type stdout there was never an error displayed like this in the whole log file. To solve it i simply added requirements.txt as a command on fluentd.

To Reproduce
Run a python script with a non-installed pip library as superuser. Fluentd never displays the error.

Expected behavior
On the terminal, Fluentd should output this missing module error.

Your Environment

• Fluentd or td-agent version: 0.14
• Operating system: Debian KVM Virtual Machine

Your Configuration

<source>
  @type exec
  @id exec_input
  tag somescript
  command python /home/SOMEUSER/Desktop/script.py
  run_interval 5s
  <parse>
    @type none
  </parse>
</source>

<match somescript>
  @type stdout
</match>

<source>
  @type tail
  @id tail_input
  read_from_head true
  path /home/SOMEUSER/Desktop/logs/*
  refresh_interval 1s
  tag debug.test
  <parse>
    @type none
  </parse>
</source>

<match debug.test>
  @type stdout
</match>

Your Error Log

root@debian:/home/zohair# export GEM_PATH=/opt/slapgrid/ff45fb5f38360191852c6436b7127bbd/parts/fluentd/lib/ruby/gems/1.8/
root@debian:/home/zohair# /opt/slapgrid/ff45fb5f38360191852c6436b7127bbd/parts/fluentd/bin/fluentd -vv -c /srv/slapgrid/slappart9/etc/fluentd-agent.conf
2020-07-27 14:57:45 +0200 [info]: fluent/supervisor.rb:696:read_config: reading config file path="/srv/slapgrid/slappart9/etc/fluentd-agent.conf"
2020-07-27 14:57:45 +0200 [info]: fluent/supervisor.rb:537:supervise: starting fluentd-0.14.14 pid=4169
2020-07-27 14:57:45 +0200 [info]: fluent/supervisor.rb:546:supervise: spawn command to main:  cmdline=["/opt/slapgrid/ff45fb5f38360191852c6436b7127bbd/parts/ruby/bin/ruby", "-Eascii-8bit:ascii-8bit", "/opt/slapgrid/ff45fb5f38360191852c6436b7127bbd/parts/fluentd/bin/fluentd", "-vv", "-c", "/srv/slapgrid/slappart9/etc/fluentd-agent.conf", "--under-supervisor"]
2020-07-27 14:57:46 +0200 [info]: fluent/engine.rb:114:block in configure: gem 'fluent-plugin-bin' version '0.2'
2020-07-27 14:57:46 +0200 [info]: fluent/engine.rb:114:block in configure: gem 'fluent-plugin-td' version '0.10.29'
2020-07-27 14:57:46 +0200 [info]: fluent/engine.rb:114:block in configure: gem 'fluent-plugin-wendelin' version '0.4'
2020-07-27 14:57:46 +0200 [info]: fluent/engine.rb:114:block in configure: gem 'fluentd' version '0.14.14'
2020-07-27 14:57:46 +0200 [info]: fluent/agent.rb:124:add_match: adding match pattern="debug.test" type="stdout"
2020-07-27 14:57:46 +0200 [trace]: #0 fluent/plugin.rb:140:register_impl: registered output plugin 'stdout'
2020-07-27 14:57:46 +0200 [trace]: #0 fluent/plugin.rb:140:register_impl: registered buffer plugin 'memory'
2020-07-27 14:57:46 +0200 [trace]: #0 fluent/plugin.rb:140:register_impl: registered formatter plugin 'stdout'
2020-07-27 14:57:46 +0200 [trace]: #0 fluent/plugin.rb:140:register_impl: registered formatter plugin 'json'
2020-07-27 14:57:46 +0200 [info]: fluent/agent.rb:124:add_match: adding match pattern="sensor_1.log-raw-data" type="wendelin"
2020-07-27 14:57:46 +0200 [trace]: #0 fluent/plugin.rb:140:register_impl: registered output plugin 'wendelin'
2020-07-27 14:57:46 +0200 [trace]: #0 fluent/plugin.rb:140:register_impl: registered buffer plugin 'file'
2020-07-27 14:57:46 +0200 [info]: fluent/root_agent.rb:238:add_source: adding source type="exec"
2020-07-27 14:57:46 +0200 [trace]: #0 fluent/plugin.rb:140:register_impl: registered input plugin 'exec'
2020-07-27 14:57:46 +0200 [trace]: #0 fluent/plugin.rb:140:register_impl: registered parser plugin 'none'
2020-07-27 14:57:46 +0200 [info]: fluent/root_agent.rb:238:add_source: adding source type="tail"
2020-07-27 14:57:46 +0200 [trace]: #0 fluent/plugin.rb:140:register_impl: registered parser plugin 'regexp'
2020-07-27 14:57:46 +0200 [trace]: #0 fluent/plugin.rb:140:register_impl: registered parser plugin 'multiline'
2020-07-27 14:57:46 +0200 [trace]: #0 fluent/plugin.rb:140:register_impl: registered input plugin 'tail'
2020-07-27 14:57:46 +0200 [warn]: #0 plugin/in_tail.rb:110:configure: 'pos_file PATH' parameter is not set to a 'tail' source.
2020-07-27 14:57:46 +0200 [warn]: #0 plugin/in_tail.rb:111:configure: this parameter is highly recommended to save the position to resume tailing.
2020-07-27 14:57:46 +0200 [info]: fluent/engine.rb:150:configure: using configuration file: <ROOT>
  <source>
    @type exec
    @id exec_input
    tag "somescript"
    command "python /home/SOMEUSER/Desktop/script.py"
    run_interval 5s
    <parse>
      @type "none"
    </parse>
  </source>
<match somescript>
  @type stdout
</match>
  <source>
    @type tail
    @id tail_input
    read_from_head true
    path "/home/SOMEUSER/Desktop/logs/*"
    refresh_interval 1s
    tag "debug.test"
    <parse>
      @type "none"
    </parse>
  </source>
  <match debug.test>
    @type stdout
  </match>

2020-07-27 14:57:46 +0200 [info]: #0 fluent/engine.rb:208:run: starting fluentd worker pid=4173 ppid=4169 worker=0
2020-07-27 14:57:46 +0200 [debug]: #0 plugin/buffer.rb:114:start: buffer started instance=47320779888720 stage_size=0 queue_size=0
2020-07-27 14:57:46 +0200 [info]: #0 fluent/engine.rb:217:run: fluentd worker is now running worker=0
2020-07-27 14:57:46 +0200 [debug]: #0 plugin/output.rb:1202:enqueue_thread_run: enqueue_thread actually running
2020-07-27 14:57:46 +0200 [trace]: #0 plugin/buffer.rb:350:enqueue_all: enqueueing all chunks in buffer instance=47320779888720
2020-07-27 14:57:46 +0200 [debug]: #0 plugin/output.rb:1254:flush_thread_run: flush_thread actually running
2020-07-27 14:57:51 +0200 [debug]: #0 [exec_input] Executing command title=:exec_input spawn=[{}, "python ~/Desktop/script1.py"] mode=[:read] stderr=:discard
2020-07-27 14:57:56 +0200 [debug]: #0 [exec_input] Executing command title=:exec_input spawn=[{}, "python ~/Desktop/script1.py"] mode=[:read] stderr=:discard
2020-07-27 14:58:01 +0200 [debug]: #0 [exec_input] Executing command title=:exec_input spawn=[{}, "python ~/Desktop/script1.py"] mode=[:read] stderr=:discard
2020-07-27 14:58:06 +0200 [debug]: #0 [exec_input] Executing command title=:exec_input spawn=[{}, "python ~/Desktop/script1.py"] mode=[:read] stderr=:discard
2020-07-27 14:58:11 +0200 [debug]: #0 [exec_input] Executing command title=:exec_input spawn=[{}, "python ~/Desktop/script1.py"] mode=[:read] stderr=:discard
2020-07-27 14:58:13 +0200 [trace]: #0 plugin/buffer.rb:350:enqueue_all: enqueueing all chunks in buffer instance=47320779888720
2020-07-27 14:58:16 +0200 [debug]: #0 [exec_input] Executing command title=:exec_input spawn=[{}, "python ~/Desktop/script1.py"] mode=[:read] stderr=:discard
2020-07-27 14:58:21 +0200 [debug]: #0 [exec_input] Executing command title=:exec_input spawn=[{}, "python ~/Desktop/script1.py"] mode=[:read] stderr=:discard
2020-07-27 14:58:26 +0200 [debug]: #0 [exec_input] Executing command title=:exec_input spawn=[{}, "python ~/Desktop/script1.py"] mode=[:read] stderr=:discard
^C2020-07-27 14:58:27 +0200 [debug]: #0 fluent/supervisor.rb:581:block in install_main_process_signal_handlers: fluentd main process get SIGINT
2020-07-27 14:58:27 +0200 [info]: serverengine/server.rb:51:stop: Received graceful stop
2020-07-27 14:58:27 +0200 [debug]: #0 fluent/supervisor.rb:592:block in install_main_process_signal_handlers: fluentd main process get SIGTERM
2020-07-27 14:58:27 +0200 [debug]: #0 fluent/supervisor.rb:595:block in install_main_process_signal_handlers: getting start to shutdown main process
2020-07-27 14:58:28 +0200 [info]: #0 fluent/engine.rb:219:run: fluentd worker is now stopping worker=0
2020-07-27 14:58:28 +0200 [info]: #0 fluent/engine.rb:236:run: shutting down fluentd worker worker=0
2020-07-27 14:58:28 +0200 [debug]: #0 fluent/root_agent.rb:177:block (2 levels) in shutdown: calling stop on input plugin type=:exec plugin_id="exec_input"
2020-07-27 14:58:28 +0200 [debug]: #0 fluent/root_agent.rb:177:block (2 levels) in shutdown: calling stop on input plugin type=:tail plugin_id="tail_input"
2020-07-27 14:58:28 +0200 [debug]: #0 fluent/root_agent.rb:177:block (2 levels) in shutdown: calling stop on output plugin type=:wendelin plugin_id="object:2b09ba51fd94"
2020-07-27 14:58:28 +0200 [trace]: #0 plugin/buffer.rb:350:enqueue_all: enqueueing all chunks in buffer instance=47320779888720
2020-07-27 14:58:28 +0200 [debug]: #0 fluent/root_agent.rb:177:block (2 levels) in shutdown: calling stop on output plugin type=:stdout plugin_id="object:2b09ba43832c"
2020-07-27 14:58:28 +0200 [debug]: #0 fluent/root_agent.rb:206:block (3 levels) in shutdown: preparing shutdown input plugin type=:tail plugin_id="tail_input"
2020-07-27 14:58:28 +0200 [debug]: #0 fluent/root_agent.rb:206:block (3 levels) in shutdown: preparing shutdown input plugin type=:exec plugin_id="exec_input"
2020-07-27 14:58:28 +0200 [debug]: #0 fluent/root_agent.rb:206:block (3 levels) in shutdown: preparing shutdown output plugin type=:wendelin plugin_id="object:2b09ba51fd94"
2020-07-27 14:58:28 +0200 [debug]: #0 fluent/root_agent.rb:206:block (3 levels) in shutdown: preparing shutdown output plugin type=:stdout plugin_id="object:2b09ba43832c"
2020-07-27 14:58:28 +0200 [info]: #0 fluent/root_agent.rb:204:block (3 levels) in shutdown: shutting down input plugin type=:tail plugin_id="tail_input"
2020-07-27 14:58:28 +0200 [info]: #0 fluent/root_agent.rb:204:block (3 levels) in shutdown: shutting down input plugin type=:exec plugin_id="exec_input"
2020-07-27 14:58:28 +0200 [info]: #0 fluent/root_agent.rb:204:block (3 levels) in shutdown: shutting down output plugin type=:wendelin plugin_id="object:2b09ba51fd94"
2020-07-27 14:58:28 +0200 [info]: #0 fluent/root_agent.rb:204:block (3 levels) in shutdown: shutting down output plugin type=:stdout plugin_id="object:2b09ba43832c"
2020-07-27 14:58:28 +0200 [debug]: #0 fluent/root_agent.rb:177:block (2 levels) in shutdown: calling after_shutdown on input plugin type=:exec plugin_id="exec_input"
2020-07-27 14:58:28 +0200 [debug]: #0 fluent/root_agent.rb:177:block (2 levels) in shutdown: calling after_shutdown on input plugin type=:tail plugin_id="tail_input"
2020-07-27 14:58:28 +0200 [debug]: #0 fluent/root_agent.rb:177:block (2 levels) in shutdown: calling after_shutdown on output plugin type=:wendelin plugin_id="object:2b09ba51fd94"
2020-07-27 14:58:28 +0200 [debug]: #0 fluent/root_agent.rb:177:block (2 levels) in shutdown: calling after_shutdown on output plugin type=:stdout plugin_id="object:2b09ba43832c"
2020-07-27 14:58:28 +0200 [debug]: #0 fluent/root_agent.rb:206:block (3 levels) in shutdown: closing input plugin type=:tail plugin_id="tail_input"
2020-07-27 14:58:28 +0200 [debug]: #0 fluent/root_agent.rb:206:block (3 levels) in shutdown: closing input plugin type=:exec plugin_id="exec_input"
2020-07-27 14:58:28 +0200 [debug]: #0 fluent/root_agent.rb:206:block (3 levels) in shutdown: closing output plugin type=:wendelin plugin_id="object:2b09ba51fd94"
2020-07-27 14:58:28 +0200 [debug]: #0 plugin/buffer.rb:120:block in close: closing buffer instance=47320779888720
2020-07-27 14:58:28 +0200 [debug]: #0 fluent/root_agent.rb:206:block (3 levels) in shutdown: closing output plugin type=:stdout plugin_id="object:2b09ba43832c"
2020-07-27 14:58:28 +0200 [debug]: #0 fluent/root_agent.rb:177:block (2 levels) in shutdown: calling terminate on input plugin type=:exec plugin_id="exec_input"
2020-07-27 14:58:28 +0200 [debug]: #0 fluent/root_agent.rb:177:block (2 levels) in shutdown: calling terminate on input plugin type=:tail plugin_id="tail_input"
2020-07-27 14:58:28 +0200 [debug]: #0 fluent/root_agent.rb:177:block (2 levels) in shutdown: calling terminate on output plugin type=:wendelin plugin_id="object:2b09ba51fd94"
2020-07-27 14:58:28 +0200 [debug]: #0 fluent/root_agent.rb:177:block (2 levels) in shutdown: calling terminate on output plugin type=:stdout plugin_id="object:2b09ba43832c"
2020-07-27 14:58:29 +0200 [info]: serverengine/multi_process_server.rb:136:alive?: Worker 0 finished with status 0

Additional context

[repeatedly]

Patch: #3108