Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

systemd kill causes undefined behavior in cleanup handler #36

Closed
sarnold opened this issue Jun 2, 2020 · 1 comment · Fixed by #37
Closed

systemd kill causes undefined behavior in cleanup handler #36

sarnold opened this issue Jun 2, 2020 · 1 comment · Fixed by #37
Assignees
@sarnold
Labels
blocking This is blocked by another issue or something upstream bug Something isn't working

Comments

@sarnold
Copy link
Contributor

sarnold commented Jun 2, 2020 •
edited
Loading

No problems using openrc with cgroups, but in spite of an almost identical man page description, letting systemd kill the daemon process on stop results in undefined behavior. The "fix" is setting

KillType=none

in the unit file and letting ExecStop kill it manually.

  • does NOT shut down correctly:
    • systemd 237-3ubuntu10.41, fpnd 0.8.5, bionic
    • systemd 245.5-3, fpnd 0.8.5, Kali/rolling (focal ppa pkgs)

Correct log snippet:

2020-06-02 22:00:18 UTC node_tools.node_funcs.do_cleanup +123: INFO [5526] CLEANUP: shutting down fpn0
2020-06-02 22:00:18 UTC node_tools.network_funcs.do_net_cmd +302: INFO [5526] net cmd fpn0-down.sh result: Success
2020-06-02 22:00:18 UTC node_tools.node_funcs.do_cleanup +126: INFO [5526] CLEANUP: leaving network ID: edf70dc89ab3fb28
2020-06-02 22:00:18 UTC node_tools.node_funcs.run_ztcli_cmd +273: DEBUG [5526] got data: 200 leave OK
2020-06-02 22:00:18 UTC node_tools.node_funcs.do_cleanup +128: DEBUG [5526] CLEANUP: action leave returned: 200 leave OK
2020-06-02 22:00:18 UTC node_tools.node_funcs.do_cleanup +123: INFO [5526] CLEANUP: shutting down fpn1
2020-06-02 22:00:18 UTC node_tools.network_funcs.do_net_cmd +302: INFO [5526] net cmd fpn1-down.sh result: Success
2020-06-02 22:00:18 UTC node_tools.node_funcs.do_cleanup +126: INFO [5526] CLEANUP: leaving network ID: edf70dc89ac82488
2020-06-02 22:00:18 UTC node_tools.node_funcs.run_ztcli_cmd +273: DEBUG [5526] got data: 200 leave OK
2020-06-02 22:00:18 UTC node_tools.node_funcs.do_cleanup +128: DEBUG [5526] CLEANUP: action leave returned: 200 leave OK
2020-06-02 22:00:18 UTC node_tools.node_funcs.run_moon_cmd +345: DEBUG [5526] deorbit on 9790eaaea1 result: 200 deorbit OK
2020-06-02 22:00:18 UTC root.call +289: DEBUG [5526] * Client will send payload: [{'ses': None, 'tok': None, 'ver': 1, 'met': 'offline', 'arg': ('ddfd7368e6',), 'ref': '5633c6b4-2fa5-4c27-b14d-56b39f9a18b4'}]
2020-06-02 22:00:18 UTC node_tools.node_funcs.do_cleanup +133: DEBUG [5526] CLEANUP: offline reply: [{'ref': '5633c6b4-2fa5-4c27-b14d-56b39f9a18b4', 'result': 'ddfd7368e6'}]

Broken log snippet with an extra log command to verify the script:

2020-06-02 21:48:00 UTC daemon.stop +231: INFO [12914] Stopping...
2020-06-02 21:48:00 UTC node_tools.node_funcs.do_cleanup +123: INFO [12428] CLEANUP: shutting down fpn0
2020-06-02 21:48:00 UTC node_tools.node_funcs.do_cleanup +125: INFO [12428] CLEANUP: got net cmd: ['/usr/lib/fpnd/fpn0-down.sh']
2020-06-02 21:48:00 UTC node_tools.node_funcs.do_cleanup +123: INFO [12428] CLEANUP: shutting down fpn0
2020-06-02 21:48:00 UTC node_tools.node_funcs.do_cleanup +125: INFO [12428] CLEANUP: got net cmd: ['/usr/lib/fpnd/fpn0-down.sh']
2020-06-02 21:48:00 UTC node_tools.node_funcs.do_cleanup +123: INFO [12428] CLEANUP: shutting down fpn0
2020-06-02 21:48:00 UTC node_tools.node_funcs.do_cleanup +125: INFO [12428] CLEANUP: got net cmd: ['/usr/lib/fpnd/fpn0-down.sh']
2020-06-02 21:48:00 UTC node_tools.node_funcs.do_cleanup +123: INFO [12428] CLEANUP: shutting down fpn0
2020-06-02 21:48:00 UTC node_tools.node_funcs.do_cleanup +125: INFO [12428] CLEANUP: got net cmd: ['/usr/lib/fpnd/fpn0-down.sh']
2020-06-02 21:48:00 UTC node_tools.node_funcs.do_cleanup +123: INFO [12428] CLEANUP: shutting down fpn0
2020-06-02 21:48:00 UTC node_tools.node_funcs.do_cleanup +125: INFO [12428] CLEANUP: got net cmd: ['/usr/lib/fpnd/fpn0-down.sh']
2020-06-02 21:48:01 UTC node_tools.node_funcs.do_cleanup +123: INFO [12428] CLEANUP: shutting down fpn0
2020-06-02 21:48:01 UTC node_tools.node_funcs.do_cleanup +125: INFO [12428] CLEANUP: got net cmd: ['/usr/lib/fpnd/fpn0-down.sh']
2020-06-02 21:48:01 UTC node_tools.node_funcs.do_cleanup +123: INFO [12428] CLEANUP: shutting down fpn0
2020-06-02 21:48:01 UTC node_tools.node_funcs.do_cleanup +125: INFO [12428] CLEANUP: got net cmd: ['/usr/lib/fpnd/fpn0-down.sh']
2020-06-02 21:48:01 UTC node_tools.node_funcs.do_cleanup +123: INFO [12428] CLEANUP: shutting down fpn0
2020-06-02 21:48:01 UTC node_tools.node_funcs.do_cleanup +125: INFO [12428] CLEANUP: got net cmd: ['/usr/lib/fpnd/fpn0-down.sh']
2020-06-02 21:48:01 UTC node_tools.node_funcs.do_cleanup +123: INFO [12428] CLEANUP: shutting down fpn0
2020-06-02 21:48:01 UTC node_tools.node_funcs.do_cleanup +125: INFO [12428] CLEANUP: got net cmd: ['/usr/lib/fpnd/fpn0-down.sh']
2020-06-02 21:48:01 UTC node_tools.node_funcs.do_cleanup +123: INFO [12428] CLEANUP: shutting down fpn0
2020-06-02 21:48:01 UTC node_tools.node_funcs.do_cleanup +125: INFO [12428] CLEANUP: got net cmd: ['/usr/lib/fpnd/fpn0-down.sh']
@sarnold
Copy link
Contributor Author

sarnold commented Jun 2, 2020

Different broken log snippet after swapping function order:

# tail -n 21 /var/log/fpnd.log 
2020-06-02 22:46:46 UTC daemon.stop +231: INFO [17188] Stopping...
2020-06-02 22:46:46 UTC node_tools.node_funcs.run_moon_cmd +346: DEBUG [13689] deorbit on 9790eaaea1 result: 200 deorbit OK
2020-06-02 22:46:46 UTC root.call +289: DEBUG [13689] * Client will send payload: [{'ses': None, 'tok': None, 'ver': 1, 'met': 'offline', 'arg': ('a8a3f7aa5d',), 'ref': 'e8b57789-08cc-4c97-9527-575cc8f96f31'}]
2020-06-02 22:46:47 UTC node_tools.node_funcs.run_moon_cmd +346: DEBUG [13689] deorbit on 9790eaaea1 result: 200 deorbit OK
2020-06-02 22:46:47 UTC root.call +289: DEBUG [13689] * Client will send payload: [{'ses': None, 'tok': None, 'ver': 1, 'met': 'offline', 'arg': ('a8a3f7aa5d',), 'ref': '9931c570-4864-46d8-a3ad-46789e556088'}]
2020-06-02 22:46:47 UTC node_tools.node_funcs.run_moon_cmd +346: DEBUG [13689] deorbit on 9790eaaea1 result: 200 deorbit OK
2020-06-02 22:46:47 UTC root.call +289: DEBUG [13689] * Client will send payload: [{'ses': None, 'tok': None, 'ver': 1, 'met': 'offline', 'arg': ('a8a3f7aa5d',), 'ref': '5ec51800-4cef-4f89-a997-9600a34407c6'}]
2020-06-02 22:46:47 UTC node_tools.node_funcs.run_moon_cmd +346: DEBUG [13689] deorbit on 9790eaaea1 result: 200 deorbit OK
2020-06-02 22:46:47 UTC root.call +289: DEBUG [13689] * Client will send payload: [{'ses': None, 'tok': None, 'ver': 1, 'met': 'offline', 'arg': ('a8a3f7aa5d',), 'ref': '11843b52-0f21-4507-a29b-2c6b76f42eec'}]
2020-06-02 22:46:47 UTC node_tools.node_funcs.run_moon_cmd +346: DEBUG [13689] deorbit on 9790eaaea1 result: 200 deorbit OK
2020-06-02 22:46:47 UTC root.call +289: DEBUG [13689] * Client will send payload: [{'ses': None, 'tok': None, 'ver': 1, 'met': 'offline', 'arg': ('a8a3f7aa5d',), 'ref': '008d0a6f-13ed-466a-8417-7c941797f00b'}]
2020-06-02 22:46:47 UTC node_tools.node_funcs.run_moon_cmd +346: DEBUG [13689] deorbit on 9790eaaea1 result: 200 deorbit OK
2020-06-02 22:46:47 UTC root.call +289: DEBUG [13689] * Client will send payload: [{'ses': None, 'tok': None, 'ver': 1, 'met': 'offline', 'arg': ('a8a3f7aa5d',), 'ref': 'aa81bd30-407a-4ee5-9886-8a33e7cdbcee'}]
2020-06-02 22:46:47 UTC node_tools.node_funcs.run_moon_cmd +346: DEBUG [13689] deorbit on 9790eaaea1 result: 200 deorbit OK
2020-06-02 22:46:47 UTC root.call +289: DEBUG [13689] * Client will send payload: [{'ses': None, 'tok': None, 'ver': 1, 'met': 'offline', 'arg': ('a8a3f7aa5d',), 'ref': 'f9174243-3d14-4a50-83e7-05a7b755dabf'}]
2020-06-02 22:46:47 UTC node_tools.node_funcs.run_moon_cmd +346: DEBUG [13689] deorbit on 9790eaaea1 result: 200 deorbit OK
2020-06-02 22:46:47 UTC root.call +289: DEBUG [13689] * Client will send payload: [{'ses': None, 'tok': None, 'ver': 1, 'met': 'offline', 'arg': ('a8a3f7aa5d',), 'ref': '3a35d422-16a0-40eb-bfd9-1473f7f5c6c9'}]
2020-06-02 22:46:47 UTC node_tools.node_funcs.run_moon_cmd +346: DEBUG [13689] deorbit on 9790eaaea1 result: 200 deorbit OK
2020-06-02 22:46:47 UTC root.call +289: DEBUG [13689] * Client will send payload: [{'ses': None, 'tok': None, 'ver': 1, 'met': 'offline', 'arg': ('a8a3f7aa5d',), 'ref': '776d91c8-e0ad-4a86-afbc-a15c6c934478'}]
2020-06-02 22:46:47 UTC node_tools.node_funcs.run_moon_cmd +346: DEBUG [13689] deorbit on 9790eaaea1 result: 200 deorbit OK
2020-06-02 22:46:47 UTC root.call +289: DEBUG [13689] * Client will send payload: [{'ses': None, 'tok': None, 'ver': 1, 'met': 'offline', 'arg': ('a8a3f7aa5d',), 'ref': 'fd8a705c-ae18-4a4c-b9b1-df7916601419'}]

@sarnold sarnold self-assigned this Jun 3, 2020
@sarnold sarnold added bug Something isn't working distro OS or distro runtime environment and removed distro OS or distro runtime environment labels Jun 3, 2020
@sarnold sarnold changed the title cleaup functions broken on shutdown (with focal pkgs on kali/rolling) cleanup functions broken on shutdown (with focal pkgs on kali/rolling) Jun 3, 2020
@sarnold sarnold added the blocking This is blocked by another issue or something upstream label Jun 4, 2020
sarnold added a commit that referenced this issue Jun 5, 2020
@sarnold
fixes for github issues #35 and #36 plus a cleanup logging change
0dc9667 
* check for iptables-legacy and use it if found
* stop letting systemd kill anything and manually send the TERM signal

Signed-off-by: Stephen Arnold <nerdboy@gentoo.org>
@sarnold sarnold mentioned this issue Jun 5, 2020
Merged
@sarnold sarnold changed the title cleanup functions broken on shutdown (with focal pkgs on kali/rolling) systemd kill causes undefined (ie, crazy) behavior in cleanup handler Jun 5, 2020
@sarnold sarnold changed the title systemd kill causes undefined (ie, crazy) behavior in cleanup handler systemd kill causes undefined behavior in cleanup handler Jun 5, 2020
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@sarnold sarnold

Labels
blocking This is blocked by another issue or something upstream bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

fixes for iptables/nf_tables and systemd execstop craziness freepn/fpnd
1 participant
@sarnold