tstack / lnav

Log file navigator
http://lnav.org
BSD 2-Clause "Simplified" License
7.99k stars 322 forks source link

SQL command history #594

Open cw1nte opened 5 years ago

cw1nte commented 5 years ago

I notice when developing adventurous sqlite code that all the failed lines get added to the sql.history. This makes the history larger and sometimes makes the good code hard to pick out! It might be better to only add commands that are not errors, if possible. A further option or nicety might be to have control (via environment variable?) over if only new commands are added to the history, at least in the case where

previous command is same as this command

I think that is how the bash command history environment option works. For myself I'd prefer if all previous commands were checked rather than just the immediate previous...

tstack commented 5 years ago

By "failure", do you mean that the query could not be parsed correctly? If you aren't already aware, the query will be syntax-checked if you pause while typing:

check-after-pause

You can also cancel out of the prompts by pressing (CTRL+]) and the current command should not be added to the history.

cw1nte commented 5 years ago

Yes, with syntax or not the result I was hoping for... I must admit I had not consciously recognised that interactive action going on. To give specific context I was trying a longish self join query attempting to get top 10 occurrences of errors by error level, so to avoid retyping text I was prepping each attempt in a text editor to try out various ideas for unions and joins and then pasting in. (As limit clause has to come last in complex queries I did not achieve that result yet, and moved on to other ideas...) When exploring possibilities I'd almost prefer to issue a specific "add this to history", CTRL+[ (?), this would also work well when I am just re-running a previous recalled command from history and do not want to add duplicates to my list. For some users that might be over-complicating occasional use of sql, so again maybe an env variable could make both modes available?

tstack commented 5 years ago

You can have lnav execute scripts in the | prompt. So, if you're already in a text editor, you can edit the query there and then just execute that file over-and-over. For example, if you create the following file:

~/.lnav/formats/installed/bigquery.lnav

;SELECT * FROM syslog_log
    WHERE log_procname = 'ssh'
:switch-to-view db

Note that the query can cross multiple lines

You can execute it in lnav by doing:

|bigquery
cw1nte commented 5 years ago

That is very handy, I tried it but added ; at end of the SQL line - seems it works fine without but I was a bit surprised. I note that the sql.history seems to only get written at exit (correct quit rather than crashes?) of lnav... Be interested to know where they live before that.. can't see sql in schema... It does seem to leave a blank line between sessions which is very useful!

On the input checking, typing "select " I only see

sql error: incomplete input select (remains lowercase, in dark blue)

rather than any change to caps as per your animation, nor seeing the command help synopsis. I am using top of tree as at a few weeks ago... I do see capitalisation if I employ autocompletion, e.g. I type sele<tab> but still not seeing the syntax info.

Ahhh, this may be a window size thing? I normally run in a smallish windows (20 vertical lines) so as to fit 4 or more windows open. I just enlarged to over 40 and see the syntax info....

cw1nte commented 5 years ago

Here is my latest query, since I could not find a way to make a SQLITE compound select to do what I wanted (top N of each type of error, though I can do 3 different limits now). ON the way a few questions arose... Where would I view any available timing info & system responses to each line on the script, if possible? e.g. SQL Result: 57 rows matched in 0.001 seconds Can I carry over the loglevel collation order used in log_level? (I could not see where this existed!) Did I miss a better way to do this as a single query? (sqlite allows only one & terminal limit clause?) Could I access the numeric loglevel? (then I can do math to balance level & total in queries) What is the persistence of my table? PS I know the histogram view gives an excellent summary of time based results of the following...

;DROP table CHWTopSyslog;
;CREATE table CHWTopSyslog AS
    SELECT  regexp_replace(log_procname,log_pid,"") AS Name, 
    log_level as level, 
    count(*) AS total, 
    count(distinct log_pid) AS PIDS 
    FROM syslog_log where level = "error"
    GROUP BY level, Name
    ORDER BY total DESC
    limit 15;
;INSERT into CHWTopSyslog  
    SELECT  regexp_replace(log_procname,log_pid,"") AS Name, 
    log_level as level, 
    count(*) AS total, 
    count(distinct log_pid) AS PIDS 
    FROM syslog_log where level = "warning"
    GROUP BY level, Name
    ORDER BY total DESC
    limit 15;
;INSERT into CHWTopSyslog  
    SELECT  regexp_replace(log_procname,log_pid,"") AS Name, 
    log_level as level, 
    count(*) AS total, 
    count(distinct log_pid) AS PIDS 
    FROM syslog_log where level = "info"
    GROUP BY level, Name
    ORDER BY total DESC
    limit 15;
;SELECT * from CHWTopSyslog ORDER BY total DESC; 

:switch-to-view db
cw1nte commented 5 years ago

Would that second line be better as ;CREATE VIRTUAL table CHWTopSyslog AS maybe I should do some reading up.... all the other tables seem set as VIRTUAL! However when I try it it seems to fail although I get no feedback as to why etc. I also see many .(dot) directives seem unavailable, such as .show I assume this is for stability/safety but is there a backdoor I can use to explore a bit more? (I was trying .log myrscriptrun and .log off at start end of my script to look into the VIRTUAL failure and was hoping to move on to .timer info)

tstack commented 5 years ago

Would that second line be better as

;CREATE VIRTUAL table CHWTopSyslog AS

You're looking to create a view and not a table. The VIRTUAL tables are implemented in native code inside of lnav.

The dot directives are a feature of the SQLite command-line client and I haven't gotten around to implementing them in lnav.

cw1nte commented 5 years ago

I thought a view must be based on (or is almost an alias of) a query, and I could not find any form of union or self or other join that gave me top N within M groups. The table form above works great as is... selecting the most frequent errors at each error level. Dot directives I guessed you were just passing to some built in SQLite command line, probably not worth the work to have to code them. Is there a way I can attach an external shell hosted SQLite command line to the lnav tables? That would open up anything I might want to explore, although the option to use full SQLite in scripts looks useful... Getting that old SQL glow!

tstack commented 5 years ago

I thought a view must be based on (or is almost an alias of) a query, and I could not find any form of union or self or other join that gave me top N within M groups. The table form above works great as is... selecting the most frequent errors at each error level.

Ah, sorry, I didn't look closely enough and didn't quite get what you were doing. I'll play with it a bit today and see if I can come up with a real answer.

Dot directives I guessed you were just passing to some built in SQLite command line, probably not worth the work to have to code them. Is there a way I can attach an external shell hosted SQLite command line to the lnav tables? That would open up anything I might want to explore, although the option to use full SQLite in scripts looks useful... Getting that old SQL glow!

An in-memory database is used by lnav, so any tables created are stored there by default and lost on exit. But, you can ATTACH a database file and create tables inside there so that your work is saved.

For example, you can attach the file doing something like:

ATTACH DATABASE 'syslog_stats.db' as syslog_stats;

And then prefix the table name with the DB name:

CREATE TABLE syslog_stats.CHWTopSyslog ...
cw1nte commented 5 years ago

That is very useful info, thanks. Can I attach to the lnav :memory: main database by some means from sqlite3 ? I'm guessing I need some form of URI/name/provider, or maybe it is just not set-up to be shared or inter-process security imposes extra steps ? It is fine for this TopSyslog to die with lnav session as it is so trivial to recreate, but great to know how to persist any significant items I may come across in future, saving all my copy/paste notes maybe

cw1nte commented 5 years ago

Of course a VIEW would be preferred over the snapshot table made by my script as the view will update as data arrives... reading a bit on in-memory sqlite databases it looks like sharing outside a process may not be easy: `ATTACH DATABASE 'file::memory:?cache=shared' AS aux1;

This allows separate database connections to share the same in-memory database. Of course, all database connections sharing the in-memory database need to be in the same process. The database is automatically deleted and memory is reclaimed when the last connection to the database closes.` https://www.sqlite.org/inmemorydb.html

cw1nte commented 5 years ago

How easy might it be to have a lnav switch for file based db? How do we know the memory footprint of lnav database? (I thought I might track this down but failed so far!) [sorry all the edits, spell check constantly makes lnav into nav]

cw1nte commented 5 years ago

For instance, nice info in sqlite3 when attempt to connect makes new empty db:

sqlite> ATTACH DATABASE 'file::memory:?cache=shared' AS lnav;
Memory Used:                         0 (max 0) bytes
Number of Outstanding Allocations:   0 (max 0)
Number of Pcache Overflow Bytes:     0 (max 0) bytes
Number of Scratch Overflow Bytes:    0 (max 0) bytes
Largest Allocation:                  0 bytes
Largest Pcache Allocation:           0 bytes
Largest Scratch Allocation:          0 bytes
Lookaside Slots Used:                10 (max 34)
Successful lookaside attempts:       137
Lookaside failures due to size:      40
Lookaside failures due to OOM:       0
Pager Heap Usage:                    18512 bytes
Page cache hits:                     3
Page cache misses:                   0
Page cache writes:                   0
Schema Heap Usage:                   2176 bytes
Statement Heap/Lookaside Usage:      1696 bytes
Fullscan Steps:                      0
Sort Operations:                     0
Autoindex Inserts:                   0
Virtual Machine Steps:               7
sqlite> .databases
seq  name             file
0    main
2    lnav
tstack commented 5 years ago

I was able to come up with a single that uses a CTE and does a bunch of UNIONS:

;WITH syslog_by_level AS
   (SELECT regexp_replace(log_procname,log_pid,"") AS Name, 
    log_level collate loglevel as level,
    count(*) AS total, 
    count(distinct log_pid) AS PIDS 
    FROM syslog_log
    GROUP BY level, Name
    ORDER BY total DESC)
 SELECT * FROM (SELECT * FROM syslog_by_level WHERE level = 'error' LIMIT 15)
 UNION
 SELECT * FROM (SELECT * FROM syslog_by_level WHERE level = 'warning' LIMIT 15)
 UNION
 SELECT * FROM (SELECT * FROM syslog_by_level WHERE level = 'info' LIMIT 15)
 ORDER BY total DESC
:switch-to-view db

Not sure if this is really an improvement over your approach ;)

cw1nte commented 5 years ago

Thanks, useful for me to see how SQLite prefers its spaghetti served! Just 3 meatballs... 3 meatballs... Also putting it inline for ; execution I could see it was .046s to run compared to .014s to just take first 45 from the simple syslog_by_level query. So no great overhead beyond 3 runs of a query it seems... The top results of the simple and union queries are the same but the union forces more of the (less frequent) warnings into results.

Can't see how long my approach, into a table runs, although it leaves the result for optional review later rather than re-run query. Any thoughts on external sqlite3 attaching to the :memory: db? I'd still like to use the (assumed) numeric collation in "log_level text collate log level" I could achieve this adding an extra text to value lookup table but that seems peverse... Aim is to weight errors and warnings more than info.

cw1nte commented 5 years ago

Would be useful to substitute parameters in script queries, but not sure how the syntax runs, have had a few tries:

log_body_like.lnav containing following script:
# @synopsis: log_body_like <text in syslog log body>
# @description: Table list matching log lines from syslog files open.
:eval ;select rightstr(substr(log_time,1,19),14) as dTime, log_body 
    from syslog_log 
    where log_body like "$1"
    ORDER by log_time DESC;
:switch-to-view db

Maybe single line only? but also no luck with any of none, single or double quotes or \escaped e.g. \"

:eval ;select log_time as dTime, log_body from syslog_log where log_body like "$1" ORDER by log_time DESC;
:switch-to-view db

|log_body_like iTunes

A little example in docs would help!! If there is a single line requirement maybe cannot add synopsis, description? (which I did have in lines 1&2 during my tests!)

tstack commented 5 years ago

Sorry that errors aren't reported in a clearer fashion. For now, run lnav with something like '-d /path/to/file' to write the internal lnav log to a file.

For your query, remember that the SQL LIKE uses '%' as a wildcard. Otherwise, it will do an exact match. So, in your example, I think it's searching for a log_body that is exactly 'iTunes'. You can either add the wildcards somewhere or use a function like instr().

As for doing substitutions, the SQL query supports bound variables. So, in the parts of the SQL where you can put an expression, you can use the dollar variable directly. For example, the query in your script can be rewritten as follows:

;select rightstr(substr(log_time,1,19),14) as dTime, log_body 
    from syslog_log 
    where log_body like $1
    ORDER by log_time DESC;

And, that should work, so long as you run it like |log_body_like %iTunes%. If you wanted to add the wildcards automatically, you could build the search string like so:

;select rightstr(substr(log_time,1,19),14) as dTime, log_body 
    from syslog_log 
    where log_body LIKE ('%' || $1 || '%')
    ORDER by log_time DESC;

For cases where you need to do a substitution in a part of the query that is not an expression, then :eval is appropriate. For example, if you wanted to parameterize the column and have it be passed in as $2:

:eval ;select rightstr(substr(log_time,1,19),14) as dTime, $2 
    from syslog_log 
    where $2 LIKE ('%' || $1 || '%')
    ORDER by log_time DESC;

Any thoughts on external sqlite3 attaching to the :memory: db?

Directly attaching to the memory DB probably won't be done. But, I think there is value in having lnav switch from a memory DB to a file DB while it is running.

cw1nte commented 5 years ago

Brilliant answer, I did know about % but was unsure about escaping what and how so in the end forgot to resolve that! Thanks for all the smart spotting and information that I hope others will find if/when needed. Would it go well in the online ref Miscellaneous info on eval?

Advantages each way on how to do the query, remembering to add % versus start/end options. I'm assuming I can put multiple words into $1, maybe with "string grouping"? Will check that next!

The disc based option that could be accessed from sqlite3 sounds a good route, would there be erase/persist options? I guess erase is safest and it seems pretty fast at setting up from scratch (in memory)...

cw1nte commented 5 years ago

While we are at SQL thoughts (a bit...), and only as "it may be of interest that...":

SQL results - long lines and general display environment: can't ^w to wrap but can move left & right with arrow keys, and ^l for simple format works and shows full lines BUT not the lines in the table or log view, not sure where they were from. Also we can search/highlight etc.

If I add fixed text search highlight command to a script e.g. /iTunes it actually highlights just Tunes, consistently drops first char (and white space?) on reading the search pattern? I think / jTunes produces the same result as /iTunes. To highlight letters of iTunes I can use /xiTunes (any non space x char) The same /iTunes search done at the sql DB view command line behaves normally.

It might be useful to point out what sort of processing is done for the commands in scripts? This would help with knowing what might need escaping, how and what could be possible... With first version you gave in previous post It is useful to do log_body_like %crash%iTunes% but then cannot succeed in script with a search & highlight line such as /$1 Ideally I was wondering if bash variable editing, to change sql % into regex .*, or at least get just string between first pair of % for the versionlog_body_like %crash%iTunes%` BUT that would be easier with script formwhere log_body LIKE ('%' || $1 || '%') but I cannot get /$1 working yet anyway. Added that logging: invoked with $1 = "write" saw the result info in log 2019-01-12T12:26:46.097 I command_executor.cc:565 /Users/colinwin/.lnav//formats/installed/log_body_like.lnav:3:execute result -- 47 rows matched in 0.012 seconds` Then the highlight/substitution handling:

2019-01-12T12:26:46.098 I command_executor.cc:88 Executing: eval /x$1
2019-01-12T12:26:46.098 D lnav_commands.cc:3104 Evaluating: /x$1
2019-01-12T12:26:46.098 D lnav_commands.cc:3111 Expanded command to evaluate: /xwrite
2019-01-12T12:26:46.098 I command_executor.cc:565 /Users/colinwin/.lnav//formats/installed/log_body_like.lnav:8:execute result -- 
error: expecting argument to start with ':', ';', or '|' to signify a command, SQL query, or script to execute

Saw that last as response error text in command line area. Maybe eval can accept / too?

In -d lnav_log the command files were all looked at twice when I issued the | log_body_like write e.g. 2 sets of lines with 2019-01-12T12:26:46.076 D log_format_loader.cc:1065 Searching for script in path: /Users/colinwin/.lnav//formats//.lnav 2019-01-12T12:26:46.077 D log_format_loader.cc:1077 found script: /Users/colinwin/.lnav//formats/default/dhclient-summary.lnav

It also saw them all at startup...

Also tempted to try recursion of |sub-script

This is a bit hidden maybe but I sometimes q(quit) back too many times and drop out, I guess quick restart is pretty effective but there could be a confirm? Y step??