Print a message if a stage is taking more than 10 seconds

[Itxaka]

With a config like this:

#cloud-config

stages:
  initramfs:
    - name: "test"
      commands:
        - sleep 15
        - echo "hello"

This is the output:

$ LOGLEVEL=debug go run main.go -s initramfs .
INFO[0000] yip version -g                               
INFO[0000] Running stage: initramfs                     
DEBU[0000] Generating op for stage 'test.yaml.0'        
DEBU[0000] Generating op for stage 'test.yaml.test'     
DEBU[0000] Reading 'test.yaml'                          
DEBU[0000] Executing stage 'test.yaml.0'                
INFO[0000] Processing stage step 'test.yaml.0'. ( commands: 0, files: 0, ... ) 
DEBU[0000] Stage: schema.Stage{}                        
DEBU[0000] Device field empty, skipping layout plugin   
DEBU[0000] Reading 'test.yaml'                          
DEBU[0000] Executing stage 'test.yaml.test'             
INFO[0000] Processing stage step 'test.yaml.test'. ( commands: 2, files: 0, ... ) 
DEBU[0000] Stage: schema.Stage{
  Commands: []string{
    "sleep 15",
    "echo \"hello\"",
  },
  Name: "test",
} 
DEBU[0000] running command `sleep 15`                   
INFO[0010] Still running command 'sleep 15'             
DEBU[0015] Empty command output                         
DEBU[0015] running command `echo "hello"`               
DEBU[0015] Command output: hello                        
DEBU[0015] Device field empty, skipping layout plugin   
INFO[0015] Done executing stage 'initramfs'    

[Itxaka]

$ LOGLEVEL=debug go run main.go -s initramfs .
INFO[0000] yip version -g                               
INFO[0000] Running stage: initramfs                     
DEBU[0000] Generating op for stage 'test.yaml.0'        
DEBU[0000] Generating op for stage 'test.yaml.test'     
DEBU[0000] Reading 'test.yaml'                          
DEBU[0000] Executing stage 'test.yaml.0'                
INFO[0000] Processing stage step 'test.yaml.0'. ( commands: 0, files: 0, ... ) 
DEBU[0000] Stage: schema.Stage{}                        
DEBU[0000] Device field empty, skipping layout plugin   
DEBU[0000] Reading 'test.yaml'                          
DEBU[0000] Executing stage 'test.yaml.test'             
INFO[0000] Processing stage step 'test.yaml.test'. ( commands: 2, files: 0, ... ) 
DEBU[0000] Stage: schema.Stage{
  Commands: []string{
    "sleep 15",
    "sleep 12",
  },
  Name: "test",
} 
DEBU[0000] running command `sleep 15`                   
INFO[0005] Still running command 'sleep 15'             
INFO[0010] Still running command 'sleep 15'             
INFO[0015] Still running command 'sleep 15'             
DEBU[0015] Empty command output                         
DEBU[0015] running command `sleep 12`                   
INFO[0020] Still running command 'sleep 12'             
INFO[0025] Still running command 'sleep 12'             
DEBU[0027] Empty command output                         
DEBU[0027] Device field empty, skipping layout plugin   
INFO[0027] Done executing stage 'initramfs'           

[Itxaka]

so the problem seems that in the case of the rsync we needed the channel to pass back the info about the rsync output, but here we just need to print a info message, nothing more

[mudler]

isn't this redundant? we do already call defer cancel()

[Itxaka]

umm that its true, maybe I was testing this manually or something?

[mudler]

so the problem seems that in the case of the rsync we needed the channel to pass back the info about the rsync output, but here we just need to print a info message, nothing more

right, but the new changes looks good - with the first round we were keeping the goroutine alive because it was not being closed at all. Now we bind it to the context which gets canceled after we finish running the command (which makes sense).

[mudler]

Just to call it out explicitly here: this covers only shell commands, not all other plugins. Can't we make at this point hook at the plugin execution? that way could cover also other cases (e.g. fetching userdata over slow network, etc)

[Itxaka]

Just to call it out explicitly here: this covers only shell commands, not all other plugins. Can't we make at this point hook at the plugin execution? that way could cover also other cases (e.g. fetching userdata over slow network, etc)

I dont know tbh, its it possible for other sources to take this long? We are talking seconds here for a "big" delay, so maybe other sources are not prone to be this slow? While commands can be really slow, like a script that waits for a service to be up and such?

But yeah, it may be trivial to adapt this to it so maybe its possible to just plugin it in before the plugin is executed

[Itxaka]

@mudler how about now?

$ LOGLEVEL=debug go run main.go -s initramfs .
INFO[0000] yip version -g                               
INFO[0000] Running stage: initramfs                     
DEBU[0000] Generating op for stage 'test.yaml.0'        
DEBU[0000] Generating op for stage 'test.yaml.test'     
DEBU[0000] Reading 'test.yaml'                          
DEBU[0000] Executing stage 'test.yaml.0'                
INFO[0000] Processing stage step 'test.yaml.0'. ( commands: 0, files: 0, ... ) 
DEBU[0000] Stage: schema.Stage{}                        
DEBU[0000] Device field empty, skipping layout plugin   
DEBU[0000] Reading 'test.yaml'                          
DEBU[0000] Executing stage 'test.yaml.test'             
INFO[0000] Processing stage step 'test.yaml.test'. ( commands: 2, files: 0, ... ) 
DEBU[0000] Stage: schema.Stage{
  Commands: []string{
    "sleep 15",
    "sleep 12",
  },
  Name: "test",
} 
DEBU[0000] running command `sleep 15`                   
INFO[0010] Still running stage 'test.yaml.test'         
DEBU[0015] Empty command output                         
DEBU[0015] running command `sleep 12`                   
INFO[0020] Still running stage 'test.yaml.test'         
DEBU[0027] Empty command output                         
DEBU[0027] Device field empty, skipping layout plugin   
INFO[0027] Done executing stage 'initramfs'             

on info:

$ go run main.go -s initramfs .
INFO[0000] yip version -g                               
INFO[0000] Running stage: initramfs                     
INFO[0000] Processing stage step 'test.yaml.0'. ( commands: 0, files: 0, ... ) 
INFO[0000] Processing stage step 'test.yaml.test'. ( commands: 2, files: 0, ... ) 
INFO[0010] Still running stage 'test.yaml.test'         
INFO[0020] Still running stage 'test.yaml.test'         
INFO[0027] Done executing stage 'initramfs'      

[mudler]

Perfect! thank you @Itxaka !