Jordi Bosch Maurell
Jordi Bosch Maurell

Reputation: 1

Why ruby snap 3.4.2 output isn't seen via journalctl when executed as a systemd service?

Well I'm not sure if I'm missing something, so since I've not been able to find anything about the cause, maybe this info can be helpful to someone in the future.

The ruby code monitors a bitaxe and reports via mail when temperature is too high, is unresponsive or doesn't perform at the expected level.

On Ubuntu 24.04 with apt installed ruby 3.2.1 ( upgraded from 20.04 and then 22.04), the ruby code runs well, and the output can be viewed using 'journalctl -u unit_name'.

When configured the code in a freshly Ubuntu 24.04 PC, i realized than journalctl only reports these type of lines:

de febr. 21 21:38:20 cirera systemd[1]: Stopped bitaxe.service - Bitaxe monitor service. de febr. 21 22:50:14 cirera systemd[1]: Started bitaxe.service - Bitaxe monitor service.

Code uses puts to display messages, but tried also with logger.info without luck. IMHO, snap doesn't allow messages can be written to logs due to permission related issues.

Workaround can be use ruby apt version, but comments are welcome in case someone can contribute, can anyone see something missing?

Thanks in advance!

BTW, here is the systemd service file:

[Unit]
Description=Bitaxe monitor service
After=network.target
After=systemd-user-sessions.service
After=network-online.target
 
[Service]
User=jordi
Type=simple
WorkingDirectory=/home/jordi
#PIDFile=/home/jordi/bitaxe_mon/server.pid
ExecStart=/snap/bin/ruby /home/jordi/bitaxe_mon/mon_bitaxeplus.rb
ExecStop=/bin/kill "$MAINPID"
#ExecStop=/bin/kill -s QUIT $MAINPID
TimeoutSec=30
Restart=on-failure
RestartSec=30
StartLimitInterval=350
StartLimitBurst=10
 
[Install]
WantedBy=multi-user.target
Alias=bitaxemon.service

What I've tried:

ruby apt version 3.2.3 is able to write output messages to be viewed by journalctl. In fact after deinstalling ruby apt and install the ruby snap 3.4.2 version, output isn't seen anymore.

Added more details as @Vy-Do suggest (thanks for answering and for interest):

I've prepared the code to illustrate the behaviour. Here is demo.rb, a loop which outputs messages using puts and logger every 120 seconds:

#!/usr/bin/ruby
require 'pp'
require 'date'
require 'time'
require 'logger'
#
if __FILE__ == $PROGRAM_NAME
logger = Logger.new($stdout, level: Logger::INFO)
while true
    logger.info("Wait 120 seconds to next loop") 
    puts " puts : Wait 120 seconds to next loop #{Time.now.strftime("%A %Y-%b-%d %T")}"
    print "\r\n\r\n"
    sleep(120)
end
end

Output when i run it from terminal:

I, [2025-02-24T17:57:27.397737 #41344] INFO -- : Wait 120 seconds to next loop puts : Wait 120 seconds to next loop Monday 2025-Feb-24 17:57:27

I, [2025-02-24T17:59:27.397986 #41344] INFO -- : Wait 120 seconds to next loop puts : Wait 120 seconds to next loop Monday 2025-Feb-24 17:59:27

Here i configured it as a system service:

[Unit]
Description=Bitaxe monitor service
After=network.target
After=systemd-user-sessions.service
After=network-online.target

[Service]
User=jordi
Type=simple
WorkingDirectory=/home/jordi
#PIDFile=/home/jordi/bitaxe_mon/server.pid
ExecStart=/snap/bin/ruby /home/jordi/bitaxe_mon/mon_bitaxeplus.rb
ExecStop=/bin/kill "$MAINPID"
#ExecStop=/bin/kill -s QUIT $MAINPID
TimeoutSec=30
Restart=on-failure
RestartSec=30
StartLimitInterval=350
StartLimitBurst=10

[Install]
WantedBy=multi-user.target
Alias=bitaxemon.service

***************** Behaviour using Ruby snap version 3.4.2

After starting the service and wait for a few minutes, no output is show in journalctl even if we stop the service:

$ sudo systemctl status demo
● demo.service - Ruby output demo service
     Loaded: loaded (/etc/systemd/system/demo.service; enabled; preset: enabled)
     Active: active (running) since Mon 2025-02-24 18:24:19 CET; 9s ago
   Main PID: 43135 (ruby)
      Tasks: 0 (limit: 18959)
     Memory: 40.0K (peak: 10.4M)
        CPU: 49ms
     CGroup: /system.slice/demo.service
             ‣ 43135 /snap/ruby/401/bin/ruby /home/jordi/demo/demo.rb

de febr. 24 18:24:19 cirera systemd[1]: Started demo.service - Ruby output demo service.

$sudo journalctl -u demo

de febr. 24 18:21:14 cirera systemd[1]: Stopped demo.service - Ruby output demo service.

de febr. 24 18:24:19 cirera systemd[1]: Started demo.service - Ruby output demo service.

$ sudo systemctl status demo

● demo.service - Ruby output demo service
     Loaded: loaded (/etc/systemd/system/demo.service; enabled; preset: enabled)
     Active: active (running) since Mon 2025-02-24 18:24:19 CET; 8min ago
   Main PID: 43135 (ruby)
      Tasks: 0 (limit: 18959)
     Memory: 40.0K (peak: 10.4M)
        CPU: 49ms
     CGroup: /system.slice/demo.service
             ‣ 43135 /snap/ruby/401/bin/ruby /home/jordi/demo/demo.rb

de febr. 24 18:24:19 cirera systemd[1]: Started demo.service - Ruby output demo service.

$ sudo systemctl stop demo

$ sudo journalctl -u demo

de febr. 24 18:21:14 cirera systemd[1]: Stopped demo.service - Ruby output demo service.

de febr. 24 18:24:19 cirera systemd[1]: Started demo.service - Ruby output demo service. de febr. 24 18:33:22 cirera systemd[1]: Stopping demo.service - Ruby output demo service...

de febr. 24 18:33:22 cirera systemd[1]: demo.service: Deactivated successfully.

de febr. 24 18:33:22 cirera systemd[1]: Stopped demo.service - Ruby output demo service.

***************** Behaviour using Ruby apt version 3.2.3, at least the output is show after stopping service:

$ sudo systemctl status demo

● demo.service - Ruby output demo service
     Loaded: loaded (/etc/systemd/system/demo.service; enabled; preset: enabled)
     Active: active (running) since Mon 2025-02-24 18:51:49 CET; 7s ago
   Main PID: 45554 (ruby)
      Tasks: 1 (limit: 18959)
     Memory: 17.9M (peak: 18.2M)
        CPU: 70ms
     CGroup: /system.slice/demo.service
             └─45554 /usr/bin/ruby /home/jordi/demo/demo.rb

de febr. 24 18:51:49 cirera systemd[1]: Started demo.service - Ruby output demo service.

$ sudo journalctl -u demo

de febr. 24 18:21:14 cirera systemd[1]: Stopped demo.service - Ruby output demo service.

de febr. 24 18:24:19 cirera systemd[1]: Started demo.service - Ruby output demo service.

de febr. 24 18:33:22 cirera systemd[1]: Stopping demo.service - Ruby output demo service...

de febr. 24 18:33:22 cirera systemd[1]: demo.service: Deactivated successfully.

de febr. 24 18:33:22 cirera systemd[1]: Stopped demo.service - Ruby output demo service.

de febr. 24 18:42:08 cirera systemd[1]: Started demo.service - Ruby output demo service.

de febr. 24 18:47:52 cirera systemd[1]: Stopping demo.service - Ruby output demo service...

de febr. 24 18:47:52 cirera systemd[1]: demo.service: Deactivated successfully.

de febr. 24 18:47:52 cirera systemd[1]: Stopped demo.service - Ruby output demo service.

de febr. 24 18:51:49 cirera systemd[1]: Started demo.service - Ruby output demo service.

$ sudo systemctl stop demo

$ journalctl -u demo

de febr. 24 18:21:14 cirera systemd[1]: Stopped demo.service - Ruby output demo service.

de febr. 24 18:24:19 cirera systemd[1]: Started demo.service - Ruby output demo service.

de febr. 24 18:33:22 cirera systemd[1]: Stopping demo.service - Ruby output demo service...

de febr. 24 18:33:22 cirera systemd[1]: demo.service: Deactivated successfully.

de febr. 24 18:33:22 cirera systemd[1]: Stopped demo.service - Ruby output demo service.

de febr. 24 18:42:08 cirera systemd[1]: Started demo.service - Ruby output demo service.

de febr. 24 18:47:52 cirera systemd[1]: Stopping demo.service - Ruby output demo service...

de febr. 24 18:47:52 cirera systemd[1]: demo.service: Deactivated successfully.

de febr. 24 18:47:52 cirera systemd[1]: Stopped demo.service - Ruby output demo service.

de febr. 24 18:51:49 cirera systemd[1]: Started demo.service - Ruby output demo service.

de febr. 24 19:01:46 cirera systemd[1]: Stopping demo.service - Ruby output demo service...

de febr. 24 19:01:46 cirera ruby[45554]: I, [2025-02-24T18:51:49.213047 #45554] INFO -- : Wait 120 seconds to next loop

de febr. 24 19:01:46 cirera ruby[45554]: puts : Wait 120 seconds to next loop Monday 2025-Feb-24 18:51:49

de febr. 24 19:01:46 cirera ruby[45554]:

de febr. 24 19:01:46 cirera ruby[45554]:

de febr. 24 19:01:46 cirera ruby[45554]: I, [2025-02-24T18:53:49.214849 #45554] INFO -- : Wait 120 seconds to next loop

de febr. 24 19:01:46 cirera ruby[45554]: puts : Wait 120 seconds to next loop Monday 2025-Feb-24 18:53:49

de febr. 24 19:01:46 cirera ruby[45554]:

de febr. 24 19:01:46 cirera ruby[45554]:

de febr. 24 19:01:46 cirera ruby[45554]: I, [2025-02-24T18:55:49.315107 #45554] INFO -- : Wait 120 seconds to next loop

de febr. 24 19:01:46 cirera ruby[45554]: puts : Wait 120 seconds to next loop Monday 2025-Feb-24 18:55:49

de febr. 24 19:01:46 cirera ruby[45554]:

de febr. 24 19:01:46 cirera ruby[45554]:

de febr. 24 19:01:46 cirera ruby[45554]: I, [2025-02-24T18:57:49.315447 #45554] INFO -- : Wait 120 seconds to next loop

de febr. 24 19:01:46 cirera ruby[45554]: puts : Wait 120 seconds to next loop Monday 2025-Feb-24 18:57:49

de febr. 24 19:01:46 cirera ruby[45554]:

de febr. 24 19:01:46 cirera ruby[45554]:

de febr. 24 19:01:46 cirera ruby[45554]: I, [2025-02-24T18:59:49.326652 #45554] INFO -- : Wait 120 seconds to next loop

de febr. 24 19:01:46 cirera ruby[45554]: puts : Wait 120 seconds to next loop Monday 2025-Feb-24 18:59:49

de febr. 24 19:01:46 cirera ruby[45554]:

de febr. 24 19:01:46 cirera ruby[45554]:

de febr. 24 19:01:46 cirera systemd[1]: demo.service: Deactivated successfully.

de febr. 24 19:01:46 cirera systemd[1]: Stopped demo.service - Ruby output demo service.

$

Upvotes: -2

Views: 35

Answers (0)

Related Questions