search broken in splunk 6.5

[akazarov]

This probably is partially covered by
https://docs.splunk.com/Documentation/Splunk/6.5.2/ReleaseNotes/Workaroundforsearchoptimizationissue...
and
https://docs.splunk.com/Documentation/Splunk/6.5.2/ReleaseNotes/6.5.2
but in my particular case (after upgrading to splunk 6.5.2), searches are fundamentally broken. E.g. given sample events like

t=1487169791, rn=315827, part=LArBarrelPS, uname=nikiforo, msgID=rc::ApplicationSignaled, host=pc-tdq-onl-05.cern.ch, app=RootController, sev=WARNING, text="Application "CHIP" on host "pc-tdq-onl-06.cern.ch" died while exiting on signal 9. Logs are "/logs/tdaq-06-01-01/LArBarrelPS/CHIP_pc-tdq-onl-06.cern.ch_1487169011.out/err".", context="PACKAGE_NAME: RunControl. FILE_NAME: ../src/Controller/ApplicationController.cxx. FUNCTION_NAME: daq::rc::ApplicationController::pmgCallback(const std::weak_ptr<daq::rc::ApplicationController>&, daq::pmg::Process*, void*)::<lambda()>. LINE_NUMBER: 182. DATE_TIME: 1487169791.", params="application: CHIP. errStream: /logs/tdaq-06-01-01/LArBarrelPS/CHIP_pc-tdq-onl-06.cern.ch_1487169011.err. hostName: pc-tdq-onl-06.cern.ch. onExit: 1. outStream: /logs/tdaq-06-01-01/LArBarrelPS/CHIP_pc-tdq-onl-06.cern.ch_1487169011.out. signal: 9. ", quals="RunControl ", chained=0, gh=1414542713

simple search

index=ers | search sev=WARNING

returns no results, whereas the suggested workaround

index=ers | search sev=WARNING | noop search_optimization=false 

works as before with splunk-6.4. Basically search by any non-indexed field is broken. I have some fields indexed at insertion and also field extraction configured for my events, may be there is some correlation.

sample data

configuration files (props,transforms,fields).conf

[martin_mueller · Accepted solution]

From your props.conf, SEGMENTATION = none is breaking a lot of default behaviour.

When you search for sourcetype=ers sev=WARNING, splunk generates this lispy expression to retrieve events: [ AND sourcetype::ers warning ] - in English, that reads "load all events with sourcetype ers that contain the token warning". Search-time field extraction is applied afterwards, and only events with sev=WARNING are retained.

Without any segmentation happening at index-time, no tokens are stored from your raw text - the lispy expression doesn't match your event. From a token point of view, your data looks like this:

splunk cmd walklex ../var/lib/splunk/defaultdb/db/hot_v1_241/1487256154-1487256127-9832302161594969862.tsidx ""
my needle:
0 2  gh::1277266474
1 1  gh::1426638438
2 1  gh::1625825802
3 1  gh::1825107383
4 1  gh::1887359547
5 1  gh::2075624474
6 1  gh::237717435
7 1  gh::360688170
8 1  gh::969631890
9 1  gh::978720110
10 2  host::pc-tdq-mon-18.cern.ch
11 3  host::pc-tdq-onl-05.cern.ch
12 4  host::pc-tdq-onl-06.cern.ch
13 2  host::sbc-pix-rcc-l-1
14 1  msgID::MDTGnam::DecodeError
15 1  msgID::MDTGnam::GenericError
16 2  msgID::PixLib::ersMessage
17 4  msgID::ers::Issue
18 1  msgID::ipc::CorbaSystemException
19 1  msgID::is::RepositoryNotFound
20 1  msgID::rc::ApplicationSignaled
21 2  part::PixelInfr
22 2  part::part_MDT_all
23 2  rn::315904
24 7  rn::315917
25 2  rn::315919
26 2  source::Appl_PixelActionsServer-L1
27 4  source::CHIP
28 2  source::MDT-BC02-GnamMon
29 3  source::RootController
30 11  sourcetype::ers
31 11 _indextime::1487263216
32 11 date_hour::14
33 11 date_mday::16
34 11 date_minute::42
35 11 date_month::february
36 1 date_second::30
37 1 date_second::31
38 2 date_second::34
39 2 date_second::7
40 2 date_second::8
41 3 date_second::9
42 11 date_wday::thursday
43 11 date_year::2017
44 11 date_zone::0
45 2 gh::1277266474
46 1 gh::1426638438
47 1 gh::1625825802
48 1 gh::1825107383
49 1 gh::1887359547
50 1 gh::2075624474
51 1 gh::237717435
52 1 gh::360688170
53 1 gh::969631890
54 1 gh::978720110
55 2 host::pc-tdq-mon-18.cern.ch
56 3 host::pc-tdq-onl-05.cern.ch
57 4 host::pc-tdq-onl-06.cern.ch
58 2 host::sbc-pix-rcc-l-1
59 11 linecount::1
60 4 msgid::ers::issue
61 1 msgid::ipc::corbasystemexception
62 1 msgid::is::repositorynotfound
63 1 msgid::mdtgnam::decodeerror
64 1 msgid::mdtgnam::genericerror
65 2 msgid::pixlib::ersmessage
66 1 msgid::rc::applicationsignaled
67 2 part::part_mdt_all
68 2 part::pixelinfr
69 2 punct::=,_=,_=,_=,_=::,_=----,_=-,_=,_="_-____--____,____
70 1 punct::=,_=,_=,_=,_=::,_=---..,_=--,_=,_="_(__________(/)
71 1 punct::=,_=,_=,_=,_=::,_=---..,_=--,_=,_="__(_..______)_-
72 1 punct::=,_=,_=-,_=,_=::,_=---..,_=,_=,_="_""___"---.."___
73 1 punct::=,_=,_=-,_=,_=::,_=---..,_=,_=,_="__''___",_=":_._
74 1 punct::=,_=,_=-,_=,_=::,_=---..,_=,_=,_="___"(=)"___",_="
75 2 punct::=,_=,_=-,_=,_=::,_=---..,_=,_=,_="____....:_:.///:
76 2 punct::=,_=,_=-,_=,_=::,_=---..,_=,_=,_="_____:_.:___''__
77 2 rn::315904
78 7 rn::315917
79 2 rn::315919
80 2 source::appl_pixelactionsserver-l1
81 4 source::chip
82 2 source::mdt-bc02-gnammon
83 3 source::rootcontroller
84 11 sourcetype::ers
85 11 timeendpos::12
86 11 timestartpos::2

Note how it only has field::value pairs, no literal tokens. When I comment out the SEGMENTATION = none part and re-index the data, there are loads more tokens stored:

splunk cmd walklex ../var/lib/splunk/defaultdb/db/hot_v1_242/1487256129-1487256129-9832697482815478144.tsidx ""
my needle:
0 1  gh::1277266474
1 1  gh::1825107383
2 2  host::pc-tdq-onl-05.cern.ch
3 1  msgID::is::RepositoryNotFound
4 1  msgID::rc::ApplicationSignaled
5 2  rn::315917
6 2  source::RootController
7 2  sourcetype::ers
8 1 .
9 1 ../src/controller/applicationcontroller.cxx.
10 1 ../src/infodictionary.cc.
11 1 /logs/tdaq-06-01-01/lucid-bi207/chip_pc-tdq-onl-06.cern.ch_1487249718.err.
12 1 /logs/tdaq-06-01-01/lucid-bi207/chip_pc-tdq-onl-06.cern.ch_1487249718.out.
13 1 /logs/tdaq-06-01-01/lucid-bi207/chip_pc-tdq-onl-06.cern.ch_1487249718.out/err
14 1 0
15 1 01
16 2 05
17 1 06
18 2 1
19 1 1.
20 1 1277266474
21 1 1487249718
22 2 1487256129
23 2 1487256129.
24 1 182
25 1 182.
26 1 1825107383
27 1 226
28 1 226.
29 2 315917
30 1 9
31 1 9.
32 1 ::
33 2 _indextime::1487263793
34 2 app
35 2 app=rootcontroller
36 1 application
37 1 application:
38 1 applicationcontroller
39 1 applicationsignaled
40 1 are
41 2 bi207
42 1 bool
43 2 carla
44 1 cc
45 2 cern
46 2 ch
47 2 chained
48 1 chained=0
49 1 chained=1
50 1 chip
51 1 chip.
52 2 const
53 1 const.
54 2 context
55 2 context=
56 1 controller
57 1 cxx
58 1 daq
59 1 daq::pmg::process
60 1 daq::rc::applicationcontroller
61 1 daq::rc::applicationcontroller::pmgcallback
62 2 date
63 2 date_hour::14
64 2 date_mday::16
65 2 date_minute::42
66 2 date_month::february
67 2 date_second::9
68 2 date_time:
69 2 date_wday::thursday
70 2 date_year::2017
71 2 date_zone::0
72 1 died
73 1 does
74 1 err
75 1 errstream
76 1 errstream:
77 1 exist
78 1 exiting
79 2 file
80 2 file_name:
81 2 function
82 2 function_name:
83 2 gh
84 1 gh::1277266474
85 1 gh::1825107383
86 1 gh=1277266474
87 1 gh=1825107383
88 2 host
89 2 host::pc-tdq-onl-05.cern.ch
90 2 host=pc-tdq-onl-05.cern.ch
91 1 hostname
92 1 hostname:
93 1 infodictionary
94 1 int
95 1 is
96 1 is.
97 1 isinfo
98 1 isinfodictionary
99 1 isinfodictionary::update
100 1 lambda
101 2 line
102 2 line_number:
103 2 linecount::1
104 1 logs
105 2 lucid
106 2 msgid
107 1 msgid::is::repositorynotfound
108 1 msgid::rc::applicationsignaled
109 1 msgid=is::repositorynotfound
110 1 msgid=rc::applicationsignaled
111 2 name
112 1 name:
113 1 not
114 2 number
115 1 on
116 1 onexit
117 1 onexit:
118 2 onl
119 1 out
120 1 outstream
121 1 outstream:
122 2 package
123 2 package_name:
124 2 params
125 2 params=
126 2 part
127 2 part=lucid-bi207
128 2 pc
129 1 pc-tdq-onl-06.cern.ch
130 1 pc-tdq-onl-06.cern.ch.
131 1 pmg
132 1 pmgcallback
133 1 process
134 1 ptr
135 1 punct::=,_=,_=-,_=,_=::,_=---..,_=,_=,_="_""___"---.."___
136 1 punct::=,_=,_=-,_=,_=::,_=---..,_=,_=,_="__''___",_=":_._
137 2 quals
138 2 quals=
139 1 rc
140 1 repository
141 1 repositorynotfound
142 2 rn
143 2 rn::315917
144 2 rn=315917
145 2 rootcontroller
146 1 runcontrol
147 1 runcontrol.
148 1 runctrl
149 1 runctrl.
150 2 sev
151 2 sev=warning
152 1 signal
153 1 signal:
154 2 source::rootcontroller
155 2 sourcetype::ers
156 2 src
157 1 std
158 1 std::weak_ptr
159 1 string
160 2 t
161 2 t=1487256129
162 1 tdaq
163 2 tdq
164 2 text
165 2 text=
166 2 time
167 2 timeendpos::12
168 2 timestartpos::2
169 2 uname
170 2 uname=carla
171 1 update
172 2 void
173 2 warning <<<---- LOOOOOK!!! (only a count of 2 because there's a second .tsidx file for that bucket with a count of 3)
174 1 weak
175 1 while

For background on segmentation, tokens, etc. check out my .conf2016 talk: http://conf.splunk.com/files/2016/recordings/fields-indexed-tokens-and-you.mp4

With segmentation back from the dead, you can now efficiently search as intended:

sourcetype=ers sev=WARNING | stats count
5

[martin_mueller]

The key point is to not touch segmenters.conf without a very good reason, the default segmenters work very well for many cases.
If you have a good reason, do elaborate... if you don't, you're just hurting yourself needlessly.

While old data is in, you can set this in limits.conf:

[search_optimization::predicate_merge]
enabled = false

https://answers.splunk.com/answers/465888/if-youre-running-650-you-should-disable-search-opt.html

[martin_mueller]

If you search for sev=WARNING, splunk will only yield events where the field sev has the value WARNING - it's what the field=value search expression is there for. Events with msgID=WARNING won't appear if the sev value is different.

My first listing contains no sev=WARNING token because SEGMENTATION = none told Splunk to not include any tokens from the event text in the index.

Doing some filter | search another filter is really really bad splunk-foo, in any version. You're basically breaking all the optimizations Splunk has built into search on purpose... now that 6.5.x attempts to optimize away some of these on-purpose inefficiencies, stuff starts to break.

Do watch my .conf talk linked to earlier on how Splunk's supposed to use tokens from the raw event to efficiently search for events.

[akazarov]

Martin, may be you can quickly help with another problem with my data indexing: msgID is an insertion-time indexed field, however searching by this field is broken, since the formed lispy expression is wrong:

02-17-2017 17:25:18.411 INFO  UnifiedSearch - Expanded index search = ( index=ers msgid=rc* )
02-17-2017 17:25:18.411 INFO  UnifiedSearch - base lispy: [ AND index::ers rc* ]

for example for another indexed field things look like expected:

02-17-2017 17:28:50.822 INFO  UnifiedSearch - Expanded index search = ( index=ers part=Pix* )
02-17-2017 17:28:50.822 INFO  UnifiedSearch - base lispy: [ AND index::ers part::pix* ]

[martin_mueller]

Field names are case sensitive. You're searching for msgid, but have msgID defined as INDEXED=true in fields.conf.

[akazarov]

OK, I see. The key point is to have a properly cooked segmenters.conf which in my case should probably look like
[ers]
MAJOR = , ' " = \n \r \s \t %20 %3D %0A %2C
MINOR = / :
However this will have effect on freshly indexed data only, so to search on old data I need to disable this type of optimization.

[akazarov]

Martin, thanks a lot, what you say makes sense. However, I disabled the segmentation on purpose: I do not want search sev=WARNING to return me all events with any token=WARNING, e.g. if I have event with msgID=WARNING, or something with this token inside 'text' field which can contain almost anything. I do not want 'more' tokens digged out of my raw data, I need exactly 'sev=WANING'. My data for this sourcetype is well structured and I explicitly tell splunk what to index and which fields to extract at search time.

Another point: why your first tokens listing (without segmentation) does not contain any traces of 'sev=WARNING' which is present in raw data? It contains all fields which are indexed by default and which I index at insertion time. Then it is expected that sourcetype=ers sev=WARNING return nothing, but e.g. sourcetype=ers rn=315917 gives the result. 'sev' is not indexed field, this is why I do | search.

And finally... all that a) was working with splunk-6.4; and b) is working as expected with the workaround.

[dwaddle]

I would upvote this 50 times if it would let me.

[martin_mueller]

That's weird - can you share a sample file and the associated props.conf to reproduce?

Beyond that, you can always follow the limits.conf workaround from https://answers.splunk.com/answers/465888/if-youre-running-650-you-should-disable-search-opt.html to turn off the broken predicate_merge part of the optimization. Then individual searches won't have to know if they need to do the workaround or not.

[akazarov]

Thanks for your help. Data sample and configuration files are attached to original question.

[martin_mueller]

sev=WARNING should be a regular auto-extracted search-time field, and therefore should not be affected by the bugs around search optimization... how are you extracting that field if not by default key-value-extraction to cause the need for the extra |search?

[akazarov]

I do insertion-time indexing for some fields: rn, part, msgID and gh, and search-time field extraction for fields 'text', 'context', 'params', 'quals', 'chained' (defined in in props.conf). Nothing manual for 'sev'. This does not make any difference, e.g.

index=ers | search text=ROD*
does not work and requires the workaround to be appended.

[niketn]

What happens when you try
index=ers sev=WARNING

[akazarov]

Nothing returned. This type of searches works for indexed fields only, i.e. for rn, part and gh in my case. BTW it does not work for msgID either, despite that indexing is configured in the same way as for other 3 fields...