| Summary: | excessive informational log messages in gluster log files, can't get it to filter them | ||
|---|---|---|---|
| Product: | Red Hat Gluster Storage | Reporter: | Ben England <bengland> |
| Component: | glusterfs | Assignee: | Krutika Dhananjay <kdhananj> |
| Status: | CLOSED ERRATA | QA Contact: | Ben Turner <bturner> |
| Severity: | medium | Docs Contact: | |
| Priority: | high | ||
| Version: | 2.0 | CC: | amarts, gluster-bugs, kdhananj, sdharane, shaines, vbellur |
| Target Milestone: | Release Candidate | ||
| Target Release: | --- | ||
| Hardware: | All | ||
| OS: | Linux | ||
| Whiteboard: | |||
| Fixed In Version: | Doc Type: | Bug Fix | |
| Doc Text: | Story Points: | --- | |
| Clone Of: | Environment: | ||
| Last Closed: | 2013-09-23 22:32:37 UTC | Type: | Bug |
| Regression: | --- | Mount Type: | --- |
| Documentation: | --- | CRM: | |
| Verified Versions: | Category: | --- | |
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |
| Cloudforms Team: | --- | Target Upstream Version: | |
|
Description
Ben England
2012-04-13 13:49:33 UTC
planning to solve this command by command. first effort is @ http://review.gluster.org/4353 CHANGE: http://review.gluster.org/4353 (glusterd: log enhancements for volume start) merged in master by Vijay Bellur (vbellur) CHANGE: http://review.gluster.org/4382 (glusterd: log changes in volume stop (and in op sm codepath)) merged in master by Anand Avati (avati) CHANGE: http://review.gluster.org/4462 (glusterd: log changes in volume create and delete codepath) merged in master by Anand Avati (avati) CHANGE: http://review.gluster.org/4463 (glusterd: remove extra call to glusterd_volume_compute_cksum()) merged in master by Anand Avati (avati) CHANGE: http://review.gluster.org/4543 (glusterd: log changes in volume set and volume reset codepath) merged in master by Anand Avati (avati) CHANGE: http://review.gluster.org/4585 (mgmt/glusterd: Move found-brick logs to DEBUG) merged in master by Vijay Bellur (vbellur) Krutika, wanted to check if rhs-2.1 branch has all the patches listed above. If not, we would need a backport. Amar, rhs-2.1 does have all the patches submitted for this bug. When running volume start I am still seeing in etc-glusterfs-glusterd.vol.log: [2013-05-07 15:26:47.763213] I [rpc-clnt.c:961:rpc_clnt_connection_init] 0-management: setting frame-timeout to 600 [2013-05-07 15:26:47.763269] I [socket.c:3482:socket_init] 0-management: SSL support is NOT enabled [2013-05-07 15:26:47.763281] I [socket.c:3497:socket_init] 0-management: using system polling thread [2013-05-07 15:26:48.241131] I [rpc-clnt.c:961:rpc_clnt_connection_init] 0-management: setting frame-timeout to 600 [2013-05-07 15:26:48.241204] I [socket.c:3482:socket_init] 0-management: SSL support is NOT enabled [2013-05-07 15:26:48.241216] I [socket.c:3497:socket_init] 0-management: using system polling thread [2013-05-07 15:26:48.241287] I [socket.c:2237:socket_event_handler] 0-transport: disconnecting now [2013-05-07 15:26:48.254656] I [rpc-clnt.c:961:rpc_clnt_connection_init] 0-management: setting frame-timeout to 600 [2013-05-07 15:26:48.254767] I [socket.c:3482:socket_init] 0-management: SSL support is NOT enabled [2013-05-07 15:26:48.254781] I [socket.c:3497:socket_init] 0-management: using system polling thread [2013-05-07 15:26:48.254861] I [socket.c:2237:socket_event_handler] 0-transport: disconnecting now Could we clean those up as well? On both volume start and volume stop the /var/log/glusterfs/bricks/<my brick> log looks much improved. A couple pieces of feedback: 1. Easier to decipher messages. When I run gluster volume stop the only message that gets generated is: [2013-05-07 15:37:25.337381] W [glusterfsd.c:970:cleanup_and_exit] (-->/lib64/libc.so.6() [0x36ac843b70] (-->/usr/lib64/libglusterfs.so.0(synctask_wrap+0x12) [0x7fb782140c02] (-->/usr/sbin/glusterfsd(glusterfs_handle_terminate+0x15) [0x40a825]))) 0-: received signum (15), shutting down This is a great improvement WRT to cleaning up messages that we dont need to see but I feel like the messages we are displaying could be a bit more informative. What was shut down? If it was a volume which volume was shut down? Without having just run the command it would be difficult to look back at this and know the volume stop command was run. Same goes for volume start: [2013-05-07 17:18:38.501063] I [glusterfsd.c:1878:main] 0-/usr/sbin/glusterfsd: Started running /usr/sbin/glusterfsd version 3.4.0.4rhs (/usr/sbin/glusterfsd -s 10.13.129.122 --volfile-id repvol.10.13.129.122.br ick -p /var/lib/glusterd/vols/repvol/run/10.13.129.122-brick.pid -S /var/run/f6183931da455b0aa8d77208625f95a4.socket --brick-name /brick -l /var/log/glusterfs/bricks/brick.log --xlator-option *-posix.glusterd-uu id=449ceab6-5a85-4cbb-a4cc-f6738bbc85e6 --brick-port 49152 --xlator-option repvol-server.listen-port=49152) 2. While the looks of the brick log are much improved I am still seeing some noise in nfs.log and etc-glusterfs-glusterd.vol.log. Can we revisit those for volume start/stop? Comment #13 has what I am seeing for volume start, here is what I am seeing for volume stop: [2013-05-07 15:37:25.341411] I [socket.c:2237:socket_event_handler] 0-transport: disconnecting now [2013-05-07 15:37:25.351662] E [run.c:190:runner_log] 0-management: Failed to execute script: /var/lib/glusterd/hooks/1/stop/pre/S40ufo-stop.pyc --volname=repvol --last=yes [2013-05-07 15:37:25.358633] E [run.c:190:runner_log] 0-management: Failed to execute script: /var/lib/glusterd/hooks/1/stop/pre/S40ufo-stop.pyo --volname=repvol --last=yes [2013-05-07 15:37:25.358705] I [mem-pool.c:541:mem_pool_destroy] 0-management: size=2236 max=1 total=1 [2013-05-07 15:37:25.358723] I [mem-pool.c:541:mem_pool_destroy] 0-management: size=124 max=1 total=1 [2013-05-07 15:37:25.358747] I [glusterd-utils.c:1182:glusterd_service_stop] 0-management: brick already stopped [2013-05-07 15:37:25.358792] E [glusterd-utils.c:1477:glusterd_brick_unlink_socket_file] 0-management: Failed to remove /var/run/f6183931da455b0aa8d77208625f95a4.socket error: No such file or directory [2013-05-07 15:37:25.774854] I [mem-pool.c:541:mem_pool_destroy] 0-management: size=2236 max=0 total=0 [2013-05-07 15:37:25.774895] I [mem-pool.c:541:mem_pool_destroy] 0-management: size=124 max=0 total=0 [2013-05-07 15:37:26.778168] E [glusterd-utils.c:3625:glusterd_nodesvc_unlink_socket_file] 0-management: Failed to remove /var/run/b504062ac1189ba0e64032b11e3a9887.socket error: Permission denied [2013-05-07 15:37:26.778631] I [glusterd-utils.c:3659:glusterd_nfs_pmap_deregister] 0-: De-registered MOUNTV3 successfully [2013-05-07 15:37:26.778876] I [glusterd-utils.c:3664:glusterd_nfs_pmap_deregister] 0-: De-registered MOUNTV1 successfully [2013-05-07 15:37:26.779158] I [glusterd-utils.c:3669:glusterd_nfs_pmap_deregister] 0-: De-registered NFSV3 successfully [2013-05-07 15:37:26.779399] I [glusterd-utils.c:3674:glusterd_nfs_pmap_deregister] 0-: De-registered NLM v4 successfully [2013-05-07 15:37:26.779657] I [glusterd-utils.c:3679:glusterd_nfs_pmap_deregister] 0-: De-registered NLM v1 successfully [2013-05-07 15:37:26.779751] I [mem-pool.c:541:mem_pool_destroy] 0-management: size=2236 max=0 total=0 [2013-05-07 15:37:26.779771] I [mem-pool.c:541:mem_pool_destroy] 0-management: size=124 max=0 total=0 [2013-05-07 15:37:27.781631] E [glusterd-utils.c:3625:glusterd_nodesvc_unlink_socket_file] 0-management: Failed to remove /var/run/ac127e4a6f1335d530a773df4265854f.socket error: No such file or directory [2013-05-07 15:37:27.781904] I [glusterd-pmap.c:271:pmap_registry_remove] 0-pmap: removing brick /brick on port 49152 [2013-05-07 15:37:27.782296] W [socket.c:515:__socket_rwv] 0-management: readv on /var/run/b504062ac1189ba0e64032b11e3a9887.socket failed (No data available) [2013-05-07 15:37:27.782410] W [socket.c:515:__socket_rwv] 0-management: readv on /var/run/ac127e4a6f1335d530a773df4265854f.socket failed (No data available) I checked volume create/delete and everything looks good there with the exception of: [2013-05-07 18:07:38.498637] I [socket.c:3482:socket_init] 0-glusterfs: SSL support is NOT enabled [2013-05-07 18:07:38.498720] I [socket.c:3497:socket_init] 0-glusterfs: using system polling thread Are those informational messages something what we could move to debug as well? It looks like they get logged when running most gluster commands in cli.log. I even just ran gluster volume help and it logged the SSL and polling thread messages. The code fixes that were submitted to mark this BZ on QA have been resolved, hence I am marking this BZ as verified. I will open up new BZs for anything mentioned above that warrants it. Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory, and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. http://rhn.redhat.com/errata/RHBA-2013-1262.html |