How to debug scripts?

[drewish]

I'm trying to use trigger to build a static website after a commit but having a problem. The info logging indicates it exited but doesn't show any output or the process's exit code. I'd tried both the options in the config but it didn't seem to have an effect.

Is there an environment variable I can set to get more information?

[RedL0tus]

Could you please give me a look at your configuration file？ There may also be some useful information in GitHub's Webhook Settings page.

For debugging purpose, I personally suggest to write a separate script for generating the site, and only use use trigger to call that script. It would be a little easier to locate the issue this way.

[drewish]

Definitely

settings:
  host: 0.0.0.0:4567
  secret: "yup some secret"
  print_commands: true
  capture_output: true

events:
  push: |
    set -e;
    cd multivac;
    export PATH="/home/amorton/.rbenv/shims:/home/amorton/.rbenv/bin:$PATH";
    bundle exec jekyll build --config _config.yml --destination /var/www/multivac/ --trace

Then running it while it accepts a webhook:

$ ./trigger --config trigger.conf 
 INFO  trigger > Listening on IPv4 address 0.0.0.0:4567
 INFO  trigger > Started
 INFO  trigger > Received "push" event from GitHub
 INFO  trigger > Delivery ID: "a0872850-c6d4-11ea-98c9-2e89e8917ae5"
 INFO  trigger > Running commands in "push" section
 INFO  trigger > Returning 200
 INFO  trigger > Commands in "push" section exited

On the GitHub side they just simply show:

Headers

Content-Length: 2
Date: Wed, 15 Jul 2020 20:14:33 GMT

Body

OK

[RedL0tus]

Definitely

settings:
  host: 0.0.0.0:4567
  secret: "yup some secret"
  print_commands: true
  capture_output: true

events:
  push: |
    set -e;
    cd multivac;
    export PATH="/home/amorton/.rbenv/shims:/home/amorton/.rbenv/bin:$PATH";
    bundle exec jekyll build --config _config.yml --destination /var/www/multivac/ --trace

Then running it while it accepts a webhook:

$ ./trigger --config trigger.conf 
 INFO  trigger > Listening on IPv4 address 0.0.0.0:4567
 INFO  trigger > Started
 INFO  trigger > Received "push" event from GitHub
 INFO  trigger > Delivery ID: "a0872850-c6d4-11ea-98c9-2e89e8917ae5"
 INFO  trigger > Running commands in "push" section
 INFO  trigger > Returning 200
 INFO  trigger > Commands in "push" section exited

On the GitHub side they just simply show:

Headers

Content-Length: 2
Date: Wed, 15 Jul 2020 20:14:33 GMT

Body

OK

Hmm, it looks like one line of your script returned a non-zero value, and the whole script exited because you did set -e at the beginning.

You can set capture_output to false in your trigger.toml to see which line is causing that problem. I really recommend you to write your script in a separate file and call that script from trigger, which will let you be able to test that script first.

[drewish]

I'd tried capture_output both ways, mostly just hoping it would log the output but I hadn't consulted the source code. Looking at it now:

trigger/src/lib.rs

Lines 147 to 151 in fc1e007

	thread::spawn(move || {
	run_script::run(&exec.as_str(), &args, &options)
	.expect("Failed to execute command");
	info!("Commands in \"{}\" section exited", &section_name);
	});

And comparing it to the run_script example:

    // simple call to run script with only the script text
    let (code, output, error) = run_script::run_script!(
        r#"
        echo "Test"
        exit 0
        "#
    ).unwrap();

It seems like we're just discarding the exit code and output. Any reason not to log those values as well? My thought would be exit code seems like something worth including in the info level but maybe the stdout would be debug level, and stderr should just always be logged at error.

I'm a bit of a rust noob but adding some logging statements seems inside my ability level. Would you be open to a PR to add this?

[RedL0tus]

@drewish

I'd tried capture_output both ways, mostly just hoping it would log the output but I hadn't consulted the source code. Looking at it now:

I tried to set capture_output to false and print_commands to true locally, and it seems to be working...

 WARN  trigger > If you ever see @kotomei2, tell him to study for the exam!
 INFO  trigger > Listening on IPv4 address 0.0.0.0:4567
 INFO  trigger > Started
 INFO  trigger > Received "push" event from GitHub
 INFO  trigger > Delivery ID: "f134f9ce-c6f4-11ea-976a-99682be6a9aa"
 INFO  trigger > Running commands in "push" section
 INFO  trigger > Returning 200
+ cd /Users/kay/Documents/github/trigger
+ set -e
+ wwwwwww
/var/folders/y0/xl4cc4f11k1c6tmqc3dpc3qr0000gn/T/kay/run_script/8imw3Edsmu.sh: line 5: wwwwwww: command not found
 INFO  trigger > Commands in "push" section exited

trigger/src/lib.rs

Lines 147 to 151 in fc1e007

	thread::spawn(move || {
	run_script::run(&exec.as_str(), &args, &options)
	.expect("Failed to execute command");
	info!("Commands in \"{}\" section exited", &section_name);
	});

And comparing it to the run_script example:

    // simple call to run script with only the script text
    let (code, output, error) = run_script::run_script!(
        r#"
        echo "Test"
        exit 0
        "#
    ).unwrap();

It seems like we're just discarding the exit code and output. Any reason not to log those values as well?

Yes... I agree it is a silly choice, at least the return value should be kept. I can't remember why I did that.

My thought would be exit code seems like something worth including in the info level but maybe the stdout would be debug level, and stderr should just always be logged at error.

I think that would be a good choice.

I'm a bit of a rust noob but adding some logging statements seems inside my ability level. Would you be open to a PR to add this.

I should be a easy fix. I'll do that. Thank you for your suggestions.

Actually I'm waiting for Hyper to release 1.0 so that I can refactor the whole project with its underlying library rifling together without worrying about API changes too much. Current versions of rifling and trigger is kind of messy...

[drewish]

Those changes are helpful. I was able to confirm it's working correctly now. One thing that would be good is to add a note to the readme that you can enable the logging by setting RUST_LOG=trigger. Took me way too long to figure out it needed to be the module name rather than a logging level.

[drewish]

Actually tried setting that on my server inside the sytemd service script and it didn't seem to work... Anyway not going to worry right now since I've finally got the blog publishing again.

[RedL0tus]

@drewish

Those changes are helpful. I was able to confirm it's working correctly now.

I'm glad it helped.

One thing that would be good is to add a note to the readme that you can enable the logging by setting RUST_LOG=trigger. Took me way too long to figure out it needed to be the module name rather than a logging level.

Ohhhh... I forgot to write that in the README, the correct way to enable debug logging is by setting TRIGGER_LOG=debug or TRIGGER_LOG=trigger=debug. I did not use the default environment variable and forgot to mention it in the README, sorry for all the confuses caused by this.

[RedL0tus]

I published v1.1.2 on crates.io as well. You can now get the updated version with cargo install trigger.