Python script executed in rc.local does not log, unless with a non-zero code

Question

My rc.local service executes a python script on startup: it works fine but it doesn't log anywhere, unless an error occurres and exits with a non-zero code. This script runs scheduled operations, therefore it will run pending in background, unless an error occurres or it's stopped manually.

This is how my rc.local looks like:

#!/bin/sh -e
#
# rc.local
#
# This script is executed at the end of each multiuser runlevel.
# Make sure that the script will "exit 0" on success or any other
# value on error.
#
# In order to enable or disable this script just change the execution
# bits.
#
# By default this script does nothing.


cd /root/path/to/script
/root/path/to/script/venv/bin/python /root/path/to/script/main.py &
exit 0

I checked syslog file with cat /var/log/syslog | grep rc.local but it only logs when thread starts or stops (the same information of systemctl status rc-local.service):

Mar 28 12:49:07 machine-hostname systemd[1]: Starting /etc/rc.local Compatibility...
Mar 28 12:49:07 machine-hostname systemd[1]: Started /etc/rc.local Compatibility.

I tried to redirect the output to an external file by overriding stdout in python script, but it doesn't work. I use a virtual environment to avoid the installation of various required python dependencies (like requests or schedule), could it be the cause of the problem? I'm new to python and linux worlds, so maybe I'm doing some configuration mistakes

PS: I need to move in the script execution folder because the python script runs openvpn command internally, and it needs its configuration files that are in the script execution folder. Here's an example of systemctl status rc-local.service command output:

● rc-local.service - /etc/rc.local Compatibility
   Loaded: loaded (/lib/systemd/system/rc-local.service; enabled-runtime; vendor preset: enabled)
  Drop-In: /lib/systemd/system/rc-local.service.d
           └─debian.conf
   Active: active (running) since Sun 2021-03-28 12:49:07 CEST; 1h 32min ago
     Docs: man:systemd-rc-local-generator(8)
  Process: 10033 ExecStart=/etc/rc.local start (code=exited, status=0/SUCCESS)
    Tasks: 2 (limit: 4915)
   CGroup: /system.slice/rc-local.service
           ├─10038 /root/path/to/script/venv/bin/python /root/path/to/script/main.py
           └─10068 openvpn configuration-file.ovpn

mar 28 12:49:07 machine-hostname systemd[1]: Starting /etc/rc.local Compatibility...
mar 28 12:49:07 machine-hostname systemd[1]: Started /etc/rc.local Compatibility.

Here's a script snippet:

import requests
import os
import subprocess
import shutil
import fileinput
import schedule
import time
from urllib.request import urlopen


# global variables declaration
...

# functions declaration
...


if __name__ == '__main__':
    print('Starting VPN connection...')
    server_list = get_server_list(max_servers_limit) # calls a public api
    connect(server_list) # executes openvpn command

    print('Scheduling VPN connection change every {} hours'.format(change_vpn_every_hours))
    schedule.every(change_vpn_every_hours).hours.do(change_vpn_connection)

    print('Scheduling internet connection checking every {} minutes'.format(check_internet_connection_minutes))
    schedule.every(check_internet_connection_minutes).minutes.do(check_internet_connection)
    while True:
        schedule.run_pending()
        time.sleep(1)

UPDATE: It seems to log almost "randomly" or in certain situations, for example when it changes the vpn connection, not just when it ends the exeuction returning an exit code... this is the output of journalctl -u rc-local.service command (my comments start with "###" to explain what really happened):

-- Reboot --
mar 28 20:59:27 machine-hostname systemd[1]: Starting /etc/rc.local Compatibility...
mar 28 20:59:27 machine-hostname systemd[1]: Started /etc/rc.local Compatibility.
mar 29 03:05:14 machine-hostname rc.local[1063]: Starting VPN connection: connecting to [...]   ### This was happened at 20:59:27, when the script execution started
mar 29 03:05:14 machine-hostname rc.local[1063]: Searching configuration file of server with hostname XXX
mar 29 03:05:14 machine-hostname rc.local[1063]: Found server with hostname XXX
mar 29 03:05:14 machine-hostname rc.local[1063]: IP address: XXX
mar 29 03:05:14 machine-hostname rc.local[1063]: Load: 23
mar 29 03:05:14 machine-hostname rc.local[1063]: Country: Italy, City: Milan
mar 29 03:05:14 machine-hostname rc.local[1063]: Latitude: XX.X, Longitude: X.X
mar 29 03:05:14 machine-hostname rc.local[1063]: Launching openvpn...
mar 29 03:05:14 machine-hostname rc.local[1063]: ###### [COMMAND OUTPUT] ######
mar 29 03:05:14 machine-hostname rc.local[1063]: Sun Mar 28 20:59:28 2021 OpenVPN 2.4.4 x86_64-pc-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [PKCS11] [MH/PKTINFO] [A
mar 29 03:05:14 machine-hostname rc.local[1063]: Sun Mar 28 20:59:28 2021 library versions: OpenSSL 1.1.1  11 Sep 2018, LZO 2.08
mar 29 03:05:14 machine-hostname rc.local[1063]: [...] 
mar 29 03:05:14 machine-hostname rc.local[1063]: Sun Mar 28 20:59:31 2021 Initialization Sequence Completed
mar 29 03:05:14 machine-hostname rc.local[1063]: ##############################
mar 29 03:05:14 machine-hostname rc.local[1063]: Connected successfully
mar 29 03:05:14 machine-hostname rc.local[1063]: Pid: 1592
mar 29 03:05:14 machine-hostname rc.local[1063]: Scheduling VPN connection change every 12 hours
mar 29 03:05:14 machine-hostname rc.local[1063]: Scheduling internet connection checking every 5 minutes     ### The two schedulers have started
mar 29 03:05:14 machine-hostname rc.local[1063]: Checking internet connection ### This was happened at 21:05, 5 minutes after the execution
mar 29 03:05:14 machine-hostname rc.local[1063]: Internet is up
mar 29 03:05:14 machine-hostname rc.local[1063]: [...]    ### It goes on this way for 12 hours: no connection problem occurred so it hasn't restarted the connection and changed VPN...
mar 29 09:05:57 machine-hostname rc.local[1063]: Checking internet connection
mar 29 09:05:57 machine-hostname rc.local[1063]: Internet is up
mar 29 09:05:57 machine-hostname rc.local[1063]: [SCHEDULER]: Changing VPN connection    ### First change vpn scheduler execution: it really happened at 09:05
mar 29 09:05:57 machine-hostname rc.local[1063]: [SCHEDULER]: Killing process 1592
mar 29 09:05:57 machine-hostname rc.local[1063]: [SCHEDULER]: Restarting network manager
mar 29 09:05:57 machine-hostname rc.local[1063]: [SCHEDULER]: Retrieving server list
mar 29 09:05:57 machine-hostname rc.local[1063]: [SCHEDULER]: Connecting to new server
mar 29 09:05:57 machine-hostname rc.local[1063]: Searching configuration file of server with hostname XXX
mar 29 09:05:57 machine-hostname rc.local[1063]: Found server with hostname XXX
mar 29 09:05:57 machine-hostname rc.local[1063]: [...]    ### Same stuff as before...
mar 29 09:05:57 machine-hostname rc.local[1063]: Connected successfully
mar 29 09:05:57 machine-hostname rc.local[1063]: Pid: 27188
mar 29 09:05:57 machine-hostname rc.local[1063]: Checking internet connection
mar 29 09:05:57 machine-hostname rc.local[1063]: Internet is up
mar 29 09:05:57 machine-hostname rc.local[1063]: Checking internet connection

I said "randomly" because the hour in the log changes at 03:05 (when nothing special happened, it checked that internet was up...) and 09:05, when it changed the VPN connection, and by the way it has just logged some minutes ago, again when the vpn changing connection scheduler was triggered... I thought that this apparently random logging could be caused by the time.sleep() function call in python script (it is also called in the method that changes the vpn connection), but I'm not sure at all.

0sleep · Accepted Answer · 2021-03-30 21:54:45Z

1

Have you tried piping the output into a log file manually like this: python3 main.py 1> output.log 2> errors.log or just python3 main.py > everything.log (you would need to find the file where the script gets called to do this)

After reading through the python code, print() outputs to stdout (not log!), unless there is some rc.local thing i don't know about saving stdout in a log

edited Mar 30, 2021 at 21:54

answered Mar 28, 2021 at 21:16

0sleep

315 bronze badges

Yep I tried, but with no result

Daniele Zagnoni
– Daniele Zagnoni

2021-03-29 18:20:00 +00:00
Commented Mar 29, 2021 at 18:20
You can override the destination of where print() method outputs (for example in a custom log file instead of stdout): I did it but it didn't work, it created the log file but it didn't write anything in it

Daniele Zagnoni
– Daniele Zagnoni

2021-04-01 10:37:08 +00:00
Commented Apr 1, 2021 at 10:37

Add a comment |

Chris W. · Accepted Answer · 2021-03-29 16:31:54Z

0

I would try removing the &. I think systemd will put it in the background for you. Also, if it's in the background, the exit 0 will run and the shell will exit unless you have used nohup. Does that help?

answered Mar 29, 2021 at 16:31

Chris W.

1,2991 gold badge9 silver badges22 bronze badges

The ending ampersand is needed to run the script in background because the execution is pending (the script runs "forever" by scheduling certain operations, it won't have an exit code unless an error occurres): if I remove it the machine startup will get stucked to the script execution during the boot phase...

Daniele Zagnoni
– Daniele Zagnoni

2021-03-29 18:40:30 +00:00
Commented Mar 29, 2021 at 18:40
By the way, when I called only openvpn in rc.local I used nohup with the ending &, and it logged perfectly in /var/log/syslog file

Daniele Zagnoni
– Daniele Zagnoni

2021-03-29 18:47:14 +00:00
Commented Mar 29, 2021 at 18:47

Add a comment |

Stack Exchange Network

Python script executed in rc.local does not log, unless with a non-zero code

2 Answers 2

You must log in to answer this question.

Hot Network Questions

Python script executed in rc.local does not log, unless with a non-zero code

2 Answers 2

You must log in to answer this question.

Related

Hot Network Questions