{"id":480,"date":"2009-06-01T08:23:55","date_gmt":"2009-05-31T22:23:55","guid":{"rendered":"http:\/\/nsrd.wordpress.com\/?p=480"},"modified":"2018-12-12T16:05:07","modified_gmt":"2018-12-12T06:05:07","slug":"debugging-autochanger-operations","status":"publish","type":"post","link":"https:\/\/nsrd.info\/blog\/2009\/06\/01\/debugging-autochanger-operations\/","title":{"rendered":"Debugging autochanger operations"},"content":{"rendered":"

Having a strong support background, and having a preference for working in software rather than hardware, when I use NetWorker’s nsrjb<\/em> utility with tape libraries I like to get as much feedback as possible on operations.<\/p>\n

When performing command line operations with nsrjb<\/em>, this is relatively straight forward \u2013 just add on a few “-v” options to the operation. Indeed, my customers sometimes probably tire of hearing me start every nsrjb<\/em> command with:<\/p>\n

# nsrjb -vvv<\/pre>\n
It’s become such a force of habit that I literally don’t consider running it without those three verbose flags any more*. If you’re not sure why you would do this, or have never run nsrjb<\/em> with verbose flags, you should go and do it \u2013 you get a lot<\/em> more information about the progress of the operation, which can actually be very important if you’re debugging or otherwise trying to resolve hanging hardware operations.<\/p>\n
Being able to run nsrjb<\/em> in verbose mode is all well and good, but it doesn’t help you diagnose periodic or random failures if they’re only happening during backup operations. To keep track of progress on these, you need to use a setting within the jukebox<\/em> resource \u2013 the debug trace level<\/strong> option.<\/p>\n
This updates the daemon.raw<\/em> log file with extra details about autochanger operations, in a similar way to the additional details you get when you run nsrjb<\/em> with additional verbosity flags. It can be set to a number, and like the debug option for a lot of NetWorker commands, defaults to 0 (for no additional information), and can be set to ever larger numbers that generate a lot of extra information. It doesn’t generate the same<\/em> information as running nsrjb<\/em> with multiple “-v” flags, but it still helps.<\/p>\n
Now, before I go further, I’d suggest that this is probably something you shouldn’t<\/em> leave enabled all the time. That is, if you’re having an intermittent problem with a tape library, consider turning this on so that you have the option of reviewing log files from overnight backups to see if there’s any relevant\/helpful information from the time of failures. However, when you finish your debugging, turn it back off<\/em> by setting it to zero.<\/p>\n
There’s two ways you can set it \u2013 either from the command line, using nsradmin<\/em>, or from NetWorker Management Console when viewing a jukebox resource with “diagnostic” details turned on.<\/p>\n
Let’s look at nsradmin<\/em> first:<\/p>\n
# nsradmin -s nox\nNetWorker administration program.\nUse the \"help\" command for help, \"visual\" for full-screen mode.\nnsradmin> show name:; debug trace level:\nnsradmin> print type: NSR jukebox\n                        name: LTO1_LIB;\n           debug trace level: 0;\nnsradmin> update debug trace level: 9\n           debug trace level: 9;\nUpdate? y\nupdated resource id 31.0.255.110.0.0.0.0.60.6.146.73.0.0.0.0.10.0.0.1(5348)\nnsradmin> print\n                        name: LTO1_LIB;\n           debug trace level: 9;<\/pre>\n
It’s as simple as that!<\/p>\n
If you want to see it from within NMC, you’d make the changes in the “Debug Trace Level” field, as per the screen-shot below:<\/p>\n
\"Advanced
Advanced tab of Autochanger properties<\/figcaption><\/figure>\n
(The debug trace level setting is the bottom-most option on the left-hand side of this tab.)<\/p>\n
You’ll find that debug level of 9 will more than likely be more than enough for any regular fault finding exercise, as the amount of information produced by this is quite high. For instance, at the bottom of this post I’ve got output from a single operation, “nsrjb -lvvv -S 1” to the volume in slot one into a drive.<\/p>\n
Remember when you’re done of course to turn the trace level back off by setting the debug trace level to zero.<\/p>\n
nox nsrlcpd getenv_ulong(NSR_LCPD_BASEELEMOFFSET=0,0:65535, 0) returning 0\nnox nsrlcpd getenv_ulong(NSR_LCPD_NO_LOAD_EXP=0,0:1, 0) returning 0\nnox nsrlcpd getenv_ulong(NSR_LCPD_NOVUELMASC=0,0:1, 0) returning 0\nnox nsrlcpd getenv_ulong(NSR_LCPD_AUTOEJECT=0,0:1, 0) returning 0\nnox nsrlcpd getenv_ulong(NSR_LCPD_AUTOEXT=0,0:1, 0) returning 0\nnox nsrlcpd getenv_ulong(NSR_LCPD_AUTOEXT2=0,0:1, 0) returning 0\nnox nsrlcpd getenv_ulong(NSR_LCPD_RES_DRVACCESS=0,0:1, 0) returning 0\nnox nsrlcpd Event LE_CONTINUE raised for cmdid 16055\nnox nsrlcpd Processing: cmdid 16055 & cmdop 12 for event: LE_CONTINUE\nnox nsrlcpd Event LE_COMP_OK raised for cmdid 16055\nnox nsrlcpd Responder woke up due to event\nnox nsrlcpd LCPD_HDR: server:nox.anywebdb.com vers:1 jbid:LTO1_LIB cmdid:16055 is_master=yes cmdop:UPDATE.\nnox nsrlcpd ncomplete :no\nnox nsrlcpd n\nnox nsrmmgd Loading volume `Clone.001' from slot `1' into device `\/dev\/nst0'.\nnox nsrlcpd LCPD_HDR: server:nox.anywebdb.com vers:1 jbid:LTO1_LIB cmdid:16056 is_master=no cmdop:LOAD.\nnox nsrlcpd     MOVE MEDIA INFO\nnox nsrlcpd         source : S:000031\nnox nsrlcpd         source attrlist : NULL\nnox nsrlcpd         dest   : D:000001\nnox nsrlcpd Event LE_NEWCMD raised for cmdid 16056\nnox nsrlcpd Processing: cmdid 16056 & cmdop 4 for event: LE_NEWCMD\nUnable to render the following message: freeing unused errinfo with msgid 14947\n\nnox nsrlcpd Event LE_CONTINUE raised for cmdid 16056\nnox nsrlcpd Processing: cmdid 16056 & cmdop 4 for event: LE_CONTINUE\nnox nsrlcpd lg_lstat(): Calling lstat64().\nnox nsrlcpd lg_open(): Calling open64().\nnox nsrlcpd lcpd_last_status_set: OK->OK (requested OK).\nnox nsrlcpd Event LE_CONTINUE raised for cmdid 16056\nnox nsrlcpd Processing: cmdid 16056 & cmdop 4 for event: LE_CONTINUE\nnox nsrlcpd lg_lstat(): Calling lstat64().\nnox nsrlcpd lg_open(): Calling open64().\nnox nsrlcpd LCPD_HDR: server:nox.anywebdb.com vers:1 jbid:LTO1_LIB cmdid:16057 is_master=no cmdop:STATUS.\nnox nsrlcpd Responder woke up due to event\nnox nsrlcpd LCPD_HDR: server:nox.anywebdb.com vers:1 jbid:LTO1_LIB cmdid:16057 is_master=yes cmdop:STATUS.\nnox nsrlcpd pid:7606 lcp_rpc_vers:1, jb_list_len:1\nnox nsrlcpd n\nnox nsrlcpd lcpd_last_status_set: OK->OK (requested OK).\nUnable to render the following message: freeing unused errinfo with msgid 14947\n\nnox nsrlcpd Event LE_CONTINUE raised for cmdid 16056\nnox nsrlcpd Processing: cmdid 16056 & cmdop 4 for event: LE_CONTINUE\nnox nsrlcpd Event LE_COMP_OK raised for cmdid 16056\nnox nsrlcpd Responder woke up due to event\nnox nsrlcpd LCPD_HDR: server:nox.anywebdb.com vers:1 jbid:LTO1_LIB cmdid:16056 is_master=yes cmdop:LOAD.\nnox nsrlcpd ncomplete :no\nnox nsrlcpd offset:0    tag:S:000031    ok:yes full: no barcode:       ? dest:D:000001 bay:?\nnox nsrlcpd n\nnox nsrlcpd offset:0      tag:D:000001    ok:yes full:yes barcode:       ? source:S:000031 serial#:? bay:?\nnox nsrlcpd n\nnox nsrd \/dev\/nst0 Verify label operation in progress\nnox nsrd \/dev\/nst0 Mount operation in progress\nnox nsrlcpd LCPD_HDR: server:nox.anywebdb.com vers:1 jbid:LTO1_LIB cmdid:16058 is_master=no cmdop:STATUS.\nnox nsrlcpd Responder woke up due to event\nnox nsrlcpd LCPD_HDR: server:nox.anywebdb.com vers:1 jbid:LTO1_LIB cmdid:16058 is_master=yes cmdop:STATUS.\nnox nsrlcpd pid:7606 lcp_rpc_vers:1, jb_list_len:1\nnox nsrlcpd n\nnox nsrd [Jukebox `LTO1_LIB', operation # 30]. Finished with status: succeeded\nnox nsrlcpd Processing: cmdid 4294967295 & cmdop 17 for event: LE_NEWCMD\nnox nsrlcpd Event ? raised for cmdid 4294967295\nnox nsrlcpd Processing: cmdid 4294967295 & cmdop 17 for event: ?\nnox nsrlcpd lg_lstat(): Calling lstat64().\nnox nsrlcpd lg_open(): Calling open64().\nnox nsrlcpd lcpd_last_status_set: OK->OK (requested OK).\nnox nsrlcpd Polling current hw status jukebox:LTO1_LIB status:OK\nnox nsrlcpd Event ? raised for cmdid 4294967295\nnox nsrlcpd Processing: cmdid 4294967295 & cmdop 17 for event: ?\nnox nsrlcpd Event LE_COMP_OK raised for cmdid 4294967295<\/pre>\n
—
\n* With the one exception being when it’s used in scripting.<\/p>\n
debug trace level option.<\/p>\n","protected":false},"excerpt":{"rendered":"
Having a strong support background, and having a preference for working in software rather than hardware, when I use NetWorker’s…<\/p>\n","protected":false},"author":1,"featured_media":0,"comment_status":"open","ping_status":"open","sticky":false,"template":"","format":"standard","meta":{"jetpack_post_was_ever_published":false,"_jetpack_newsletter_access":"","_jetpack_dont_email_post_to_subs":false,"_jetpack_newsletter_tier_id":0,"_jetpack_memberships_contains_paywalled_content":false,"_jetpack_memberships_contains_paid_content":false,"footnotes":"","jetpack_publicize_message":"","jetpack_publicize_feature_enabled":true,"jetpack_social_post_already_shared":false,"jetpack_social_options":{"image_generator_settings":{"template":"highway","default_image_id":0,"font":"","enabled":false},"version":2}},"categories":[16,23],"tags":[130,292,294,512],"class_list":["post-480","post","type-post","status-publish","format-standard","hentry","category-networker","category-support","tag-autochanger","tag-debug","tag-debug-trace-level","tag-jukebox"],"aioseo_notices":[],"jetpack_publicize_connections":[],"jetpack_featured_media_url":"","jetpack_shortlink":"https:\/\/wp.me\/pKpIN-7K","jetpack_sharing_enabled":true,"jetpack_likes_enabled":true,"_links":{"self":[{"href":"https:\/\/nsrd.info\/blog\/wp-json\/wp\/v2\/posts\/480","targetHints":{"allow":["GET"]}}],"collection":[{"href":"https:\/\/nsrd.info\/blog\/wp-json\/wp\/v2\/posts"}],"about":[{"href":"https:\/\/nsrd.info\/blog\/wp-json\/wp\/v2\/types\/post"}],"author":[{"embeddable":true,"href":"https:\/\/nsrd.info\/blog\/wp-json\/wp\/v2\/users\/1"}],"replies":[{"embeddable":true,"href":"https:\/\/nsrd.info\/blog\/wp-json\/wp\/v2\/comments?post=480"}],"version-history":[{"count":1,"href":"https:\/\/nsrd.info\/blog\/wp-json\/wp\/v2\/posts\/480\/revisions"}],"predecessor-version":[{"id":7651,"href":"https:\/\/nsrd.info\/blog\/wp-json\/wp\/v2\/posts\/480\/revisions\/7651"}],"wp:attachment":[{"href":"https:\/\/nsrd.info\/blog\/wp-json\/wp\/v2\/media?parent=480"}],"wp:term":[{"taxonomy":"category","embeddable":true,"href":"https:\/\/nsrd.info\/blog\/wp-json\/wp\/v2\/categories?post=480"},{"taxonomy":"post_tag","embeddable":true,"href":"https:\/\/nsrd.info\/blog\/wp-json\/wp\/v2\/tags?post=480"}],"curies":[{"name":"wp","href":"https:\/\/api.w.org\/{rel}","templated":true}]}}