How to set up engine logging (debug logging)?

[Kent Multer]

Hi folks,

I need to use debug logging to track down a problem in json.mv. I've asked this question by email to Miva three times in the last few weeks, and no one has answered.

Before that, a support person sent me a link to these instructions:

https://www.miva.com/forums/forum/de...ript-debug-log

But this document doesn't tell me everything I need to set it up. I don't have expertise on Unix server setup. I need a bit of help, specifically:

1. The document gives two sets of instructions: one for the "environment-variable based configuration library," and another for the "3.x configuration library." I don't know how to tell which one my store is using.

2. The article lists three environment variables that need to be set. I don't know where those variables are or how I set them. I suppose there's a text file I have to create or edit?

The rest of the instructions seem clear enough. So if someone can tell me how to enter the commands, I should be able to get to work on this.

Thanks for your help --

[dcarver]

Are you using a mivavm.conf file or are you setting configuration settings via environment variables?

If you're using mivavm.conf, you're using 3x configuration. You need to edit your mivavm.conf file and add

loglevel=xxx
logfile=kent.log
logfilter=xxx (optional if you want to log only a specific file)

If you're using environment based configuration you need to set

MvCONFIG_LOG_LEVEL=xxx
MvCONFIG_LOG_FILE=xxx
MvCONFIG_LOG_FILTER=xxx (optional if you want to log only a specific file)

[Kent Multer]

Are you using a mivavm.conf file or are you setting configuration settings via environment variables?

I don't know; that was my question #1 above. As I said, I'm not familiar with server setups.

For the moment, I'm working in my free test store at dts2483.mivamerchantdev.com. How do I find out which config I'm using?

Thanks --

[dcarver]

You're probably using 3x. Modify the file either in /etc/mivavm.conf or mivavm.conf within the cgi-bin directory. dhubbard

[Kent Multer]

You're probably using 3x. Modify the file either in /etc/mivavm.conf or mivavm.conf within the cgi-bin directory. dhubbard

There is no /etc directory; at least, I don't see one when I log in with FTP.

There's a /cgi-bin directory, but it's empty (according to my FTP). Is it OK for me to create a mivavm.conf file and put those three commands in it?

Thanks --

[dcarver]

No. It exists somewhere. I'm not sure how support has those servers setup. I pinged DH and he should be able to clarify.

[ILoveHostasaurus]

In most cases there should be a /cgi-bin/mivavm.conf that is NOT inside /httpdocs. The exception to this is subdomain/dev sites where cgi-bin IS in the relevant httpdocs directory.

[Kent Multer]

In my dev store at the above-mentioned URL, the /cgi-bin directory is empty. The HTML root directory is named htdocs, not httpdocs; and there is no cgi-bin subdirectory in there.

I'm using the FTP credentials I was given when I got the site. I don't know if there could be a permission problem keeping me from seeing the relevant files?

Thanks --

[ids]

FWIW, I have a couple of DTS stores and the cgi-bin parallel to htdocs is empty in all of them. If Tim T. is still maintaining the DTS deployment, maybe he can advise on how to configure logging? I've wanted to configure the logging feature in the past myself.

Scott

[ILoveHostasaurus]

For DTS stores, the way to do this is via the control panel's Scripts & Databases link along the left, Miva Scripting, then the Configuration Variables box towards the bottom. You would set at least:

LOG_LEVEL=
LOG_FILE=

and possibly also LOG_COOKIE to restrict logging to the browser that has the cookie. You can set the cookie via the diagtool.mvc that comes with the Empresa distribution from our website, or your own scripts, such as using a session cookie.

The log file is just the name of the text file you'd like to have appear in mivadata.

The log level you choose comes from a combination you create based on the then-current log level options which will be found in the Empresa distribution's include/mivaapi.h file. They can be specified in hex or decimal, for example, MvCONFIG_LOG_FUNC_RETURN can be either 0x00000080 or 128. If you need multiple logging levels, you add them together, so you may find it easier to convert them to decimal and add them that way. For example, if you needed FUNC_CALL, FUNC_PARAM, FUNC_RETVAL, FUNC_RETURN, which are 10, 20, 40, and 80 in hex (16, 32, 64, 128 decimal), you would specify 240 or 0x000000F0

You can also optionally add LOG_FILTER to further restrict logging. It is documented in the Empresa distribution's doc/RELNOTE.txt file.

[Kent Multer]

Thanks for the info, David. I was able to set up logging with LOG_LEVEL=240 (16 + 32 + 64 + 128) to log function calls, parameters, returns, and return values. It's producing a log file, but what I'm seeing in there doesn't seem correct.

A little background: I'm debugging a module that uses the "json" API feature. I've been testing it by entering URLs in my browser, but I'm not getting back any response at all, not even an error message. The module has some log-keeping features of its own, and it's clear that the Module_JSON() functon is not getting called.

Once, I accidentally used a URL with an invalid store code; and in that case, I did get an error message in JSON format. But a look at the LSK shows that there are a number of places in json.mv where it exits without providing any sort of error message. So I'm using logging on json.mv (LOG_FILTER=json.mv), to figure out where it's dying.

I assumed that the log file would show the calls and returns in a nested fashion, mirroring the way that functions call other functions. But a lot of the calls and returns aren't showing up in the log file..

Here is the log file that was generated by a single call to json.mvc. I added some white space and indenting, hoping that I would be able to see all the nesting of calls and returns. But it seems like a lot of them are missing, so my indenting ended up being kind of inconsistent.

Jul 9 2021 02:58:12.732665 9358 Function Call mm5/5.00/json.mvc json.mv 31 json

Jul 9 2021 02:58:12.732697 9358 ::: Function Call mm5/5.00/json.mvc json.mv 291 json_initialize_session

Jul 9 2021 02:58:12.743196 9358 ::: ::: Function Call mm5/5.00/lib/db.mvc json.mv 72 opendatafiles_source
Jul 9 2021 02:58:12.743211 9358 ::: ::: Function Parameter mm5/5.00/lib/db.mvc json.mv 72 opendatafiles_source domain
Jul 9 2021 02:58:12.743217 9358 ::: ::: Function Parameter mm5/5.00/lib/db.mvc json.mv 72 opendatafiles_source source runtime
Jul 9 2021 02:58:12.743222 9358 ::: ::: Function Parameter mm5/5.00/lib/db.mvc json.mv 72 opendatafiles_source merchant_version 10.00.06

Jul 9 2021 02:58:12.775217 9358 ::: ::: ::: Function Call mm5/5.00/lib/util.mvc json.mv 81 determinesessionid

Jul 9 2021 02:58:12.777412 9358 ::: ::: ::: ::: Function Call mm5/5.00/lib/util.mvc json.mv 83 validatepaths

Jul 9 2021 02:58:12.777439 9358 ::: ::: ::: ::: ::: Function Call mm5/5.00/lib/db.mvc json.mv 88 store_open
Jul 9 2021 02:58:12.777445 9358 ::: ::: ::: ::: ::: Function Parameter mm5/5.00/lib/db.mvc json.mv 88 store_open store
Jul 9 2021 02:58:12.777450 9358 ::: ::: ::: ::: ::: Function Parameter mm5/5.00/lib/db.mvc json.mv 88 store_open code m

Jul 9 2021 02:58:12.788599 9358 ::: ::: ::: ::: ::: ::: Function Call mm5/5.00/lib/util.mvc json.mv 111 openbasket
Jul 9 2021 02:58:12.788612 9358 ::: ::: ::: ::: ::: ::: Function Parameter mm5/5.00/lib/util.mvc json.mv 111 openbasket basket

Jul 9 2021 02:58:12.791679 9358 ::: ::: ::: ::: ::: ::: ::: Function Call mm5/5.00/json.mvc json.mv 112 json_maintenancemode_storeclosed
Jul 9 2021 02:58:12.791693 9358 ::: ::: ::: ::: ::: ::: ::: Function Return Value json.mv 1938 json_maintenancemode_storeclosed 0
Jul 9 2021 02:58:12.791698 9358 ::: ::: ::: ::: ::: ::: ::: Function Return mm5/5.00/json.mvc json.mv 1938 json_maintenancemode_storeclosed

Jul 9 2021 02:58:12.791706 9358 ::: Function Return Value json.mv 283 json_initialize_session 1
Jul 9 2021 02:58:12.791710 9358 ::: Function Return mm5/5.00/json.mvc json.mv 283 json_initialize_session

Jul 9 2021 02:58:12.791720 9358 Function Return Value json.mv 1123 json 1
Jul 9 2021 02:58:12.791724 9358 Function Return mm5/5.00/json.mvc json.mv 1123 json

Jul 9 2021 02:58:12.793461 9358 Function Call mm5/5.00/features/sch/sch_ut.mvc json.mv 35 scheduledtasks_spawn_asynchronoustask

Jul 9 2021 02:58:13.256518 32173 Function Return Value json.mv 3050 json_encode Redirect
Jul 9 2021 02:58:13.256553 32173 Function Return mm5/5.00/json.mvc json.mv 3050 json_encode

Jul 9 2021 02:58:13.256593 32173 Function Return Value json.mv 3050 json_encode 5.35
Jul 9 2021 02:58:13.256598 32173 Function Return mm5/5.00/json.mvc json.mv 3050 json_encode

Jul 9 2021 02:58:13.256626 32173 Function Return Value json.mv 3050 json_encode https:\/\/dts2483.mivamerchantdev.com\/mm5\/json.mvc\u003F
Jul 9 2021 02:58:13.256631 32173 Function Return mm5/5.00/json.mvc json.mv 3050 json_encode

Jul 9 2021 02:58:13.256663 32173 Function Return Value json.mv 3050 json_encode https:\/\/dts2483.mivamerchantdev.com\/mm5\/json.mvc\u003F
Jul 9 2021 02:58:13.256669 32173 Function Return mm5/5.00/json.mvc json.mv 3050 json_encode

Jul 9 2021 02:58:13.256696 32173 Function Return Value json.mv 3050 json_encode m
Jul 9 2021 02:58:13.256700 32173 Function Return mm5/5.00/json.mvc json.mv 3050 json_encode

Jul 9 2021 02:58:13.271239 32173 Function Return Value json.mv 3050 json_encode https:\/\/dts2483.mivamerchantdev.com\/mm5\/merchant.mvc\u003FSession_ID\u003Dc306fd07a2762ce4 829f335bcaf8280f\u0026Screen\u003DSRCH\u0026
Jul 9 2021 02:58:13.271264 32173 Function Return mm5/5.00/json.mvc json.mv 3050 json_encode

Does this give enough info to explain why it's not calling my module?

I tried turning off the LOG_FILTER variable, but then I got a log file that was over 5000 lines long, and included calls to merchant.mvc and component modules. I don't know why a call to json.mv would result in rendering a page?

Does the LOG_FILTER variable support two or more filenames separated by commas? I'd like to enable logging for a couple more files, such as db.mv and util.mv, but not the whole store.

Thanks --

[ILoveHostasaurus]

Do you receive back a status 200? If not, you should probably add the log levels for runtime and fatal errors. I'd run it without the filter and use the long log file. It does show the PID per line (looks like 9358 in this case) so you may need to extract only the relevant lines if other requests are hitting the site and causing a mixture of multiple processes to be logged.

[Kent Multer]

According to my browser, I did get back a 200 status, if I understand this tool correctly. (Image attached.)

browser tool.png
However, I did turn off the LOG_FILTER setting and try again. This time the log file was about 200 lines: big enough that I didn't try to sort of out all the nested calls and returns, but not too big to attach to this post in case you want to have a look.

What should I try next?

Thanks for your help --